Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat: add logging for RPC subscription notifications #2021

Merged
merged 5 commits into from
Feb 21, 2025

Conversation

pedro-pelicioni-cw
Copy link
Contributor

@pedro-pelicioni-cw pedro-pelicioni-cw commented Feb 19, 2025

User description

Add detailed tracing logs for RPC subscription events, including:

  • Pending transaction notifications
  • New block header notifications
  • Log event notifications

The logs now include relevant context such as transaction hash, block number, and the number of subscribers being notified.


PR Type

Enhancement


Description

  • Add detailed tracing logs for RPC subscription events

  • Log pending transactions, new block headers, log events

  • Include context: transaction hash, block number, subscribers count

  • Improve visibility and debugging for subscription notifications


Changes walkthrough 📝

Relevant files
Enhancement
rpc_subscriptions.rs
Add tracing logs for RPC subscription events                         

src/eth/rpc/rpc_subscriptions.rs

  • Add tracing::info! logs for pending transactions
  • Implement logging for new block header notifications
  • Include logging for log event notifications
  • Log relevant context: tx hash, block number, subscribers count
  • +22/-0   

    Need help?
  • Type /help how to ... in the comments thread for any questions about PR-Agent usage.
  • Check out the documentation for more information.
  • Add detailed tracing logs for RPC subscription events, including:
    - Pending transaction notifications
    - New block header notifications
    - Log event notifications
    
    The logs now include relevant context such as transaction hash, block number, and the number of subscribers being notified.
    Copy link

    PR Reviewer Guide 🔍

    Here are some key observations to aid the review process:

    ⏱️ Estimated effort to review: 2 🔵🔵⚪⚪⚪
    🧪 No relevant tests
    🔒 No security concerns identified
    ⚡ Recommended focus areas for review

    Logging Consistency

    Ensure that the logging format and level are consistent across all three notification types (pending transactions, new blocks, and logs). Consider standardizing the field names and log levels for better consistency and easier log parsing.

                tracing::info!(
                    tx_hash = ?tx_hash,
                    subscribers_count = interested_subs.len(),
                    "notifying subscribers about new pending transaction"
                );
    
                Self::notify(interested_subs, tx_hash.to_string());
            }
            warn_task_rx_closed(TASK_NAME);
            Ok(())
        })
    }
    
    /// Spawns a new task that notifies subscribers about new created blocks.
    fn spawn_new_heads_notifier(subs: Arc<RpcSubscriptionsConnected>, mut rx_block: broadcast::Receiver<BlockHeader>) -> JoinHandle<anyhow::Result<()>> {
        const TASK_NAME: &str = "rpc::sub::newHeads";
        spawn_named(TASK_NAME, async move {
            loop {
                if GlobalState::is_shutdown_warn(TASK_NAME) {
                    return Ok(());
                }
    
                let block_header = match timeout(NOTIFIER_SHUTDOWN_CHECK_INTERVAL, rx_block.recv()).await {
                    Ok(Ok(block)) => block,
                    Ok(Err(_channel_closed)) => break,
                    Err(_timed_out) => continue,
                };
    
                let interested_subs = subs.new_heads.read().await;
                let interested_subs = interested_subs.values().collect_vec();
    
                tracing::info!(
                    block_number = ?block_header.number,
                    block_hash = ?block_header.hash,   
                    subscribers_count = interested_subs.len(),
                    "notifying subscribers about new block"
                );
    
                Self::notify(interested_subs, block_header);
            }
            warn_task_rx_closed(TASK_NAME);
            Ok(())
        })
    }
    
    /// Spawns a new task that notifies subscribers about new transactions logs.
    fn spawn_logs_notifier(subs: Arc<RpcSubscriptionsConnected>, mut rx_log_mined: broadcast::Receiver<LogMined>) -> JoinHandle<anyhow::Result<()>> {
        const TASK_NAME: &str = "rpc::sub::logs";
        spawn_named(TASK_NAME, async move {
            loop {
                if GlobalState::is_shutdown_warn(TASK_NAME) {
                    return Ok(());
                }
    
                let log = match timeout(NOTIFIER_SHUTDOWN_CHECK_INTERVAL, rx_log_mined.recv()).await {
                    Ok(Ok(log)) => log,
                    Ok(Err(_channel_closed)) => break,
                    Err(_timed_out) => continue,
                };
    
                let interested_subs = subs.logs.read().await;
                let interested_subs = interested_subs
                    .values()
                    .flat_map(HashMap::values)
                    .filter_map(|s| if_else!(s.filter.matches(&log), Some(&s.inner), None))
                    .collect_vec();
    
                tracing::info!(
                    log_block_number = ?log.block_number,
                    log_tx_hash = ?log.transaction_hash,
                    subscribers_count = interested_subs.len(),
                    "notifying subscribers about new logs"
                );

    Copy link

    PR Code Suggestions ✨

    Explore these optional code suggestions:

    CategorySuggestion                                                                                                                                    Impact
    General
    Adjust log level for frequent events

    Consider using a more appropriate log level, such as 'debug', for high-frequency
    events like transaction notifications. This will prevent log spam in production
    environments while still providing valuable information for debugging.

    src/eth/rpc/rpc_subscriptions.rs [176-180]

    -tracing::info!(
    +tracing::debug!(
         tx_hash = ?tx_hash,
         subscribers_count = interested_subs.len(),
         "notifying subscribers about new pending transaction"
     );
    Suggestion importance[1-10]: 7

    __

    Why: Changing the log level from 'info' to 'debug' for high-frequency events is a good practice. It helps prevent log spam in production while maintaining valuable debugging information, improving overall system observability.

    Medium
    Optimize logging frequency for performance

    To improve performance, consider moving the logging statement outside the loop if
    the log message doesn't change frequently. This will reduce the number of log
    writes, especially when there are many subscribers.

    src/eth/rpc/rpc_subscriptions.rs [207-212]

    +let mut last_logged_block = None;
     loop {
         // ... existing code ...
    -    tracing::info!(
    -        block_number = ?block_header.number,
    -        block_hash = ?block_header.hash,   
    -        subscribers_count = interested_subs.len(),
    -        "notifying subscribers about new block"
    -    );
    +    if last_logged_block != Some(block_header.number) {
    +        tracing::info!(
    +            block_number = ?block_header.number,
    +            block_hash = ?block_header.hash,   
    +            subscribers_count = interested_subs.len(),
    +            "notifying subscribers about new block"
    +        );
    +        last_logged_block = Some(block_header.number);
    +    }
         Self::notify(interested_subs, block_header);
     }
    Suggestion importance[1-10]: 5

    __

    Why: The suggestion to reduce logging frequency could improve performance, especially with many subscribers. However, it may slightly complicate the code and potentially miss logging some block information, which might be important for certain use cases.

    Low

    Minor formatting adjustment to the RPC subscription logging, ensuring consistent and clean tracing output for new block header notifications.
    …nformation
    
    Update tracing logs to display the actual subscribers instead of just the subscriber count for:
    - Pending transaction notifications
    - New block header notifications
    - Log event notifications
    
    This change provides more granular visibility into which subscribers are being notified during RPC events.
    Clean up tracing log comments for:
    - Pending transaction notifications
    - New block header notifications
    
    Remove unnecessary inline comments while maintaining the existing logging structure.
    Remove trailing whitespaces in tracing log statements for:
    - Pending transaction notifications
    - New block header notifications
    
    Ensure consistent and clean logging output without functional changes.
    @pedro-pelicioni-cw pedro-pelicioni-cw linked an issue Feb 21, 2025 that may be closed by this pull request
    @pedro-pelicioni-cw pedro-pelicioni-cw merged commit 4511bde into main Feb 21, 2025
    40 checks passed
    @pedro-pelicioni-cw pedro-pelicioni-cw deleted the feat/subscriber-logs-1655 branch February 21, 2025 13:24
    @gabriel-aranha-cw
    Copy link
    Contributor

    Final benchmark:
    Run ID: bench-3084069339

    Git Info:

    Configuration:

    • Target Account Strategy: Default

    Leader Stats:
    RPS Stats: Max: 2142.00, Min: 1409.00, Avg: 1988.91, StdDev: 83.08
    TPS Stats: Max: 2156.00, Min: 1719.00, Avg: 1930.44, StdDev: 97.00

    Follower Stats:
    Imported Blocks/s: Max: 2.00, Min: 1.00, Avg: 1.34, StdDev: 0.47
    Imported Transactions/s: Max: 4258.00, Min: 14.00, Avg: 2650.18, StdDev: 954.91

    Plots:

    Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
    Labels
    None yet
    Projects
    None yet
    Development

    Successfully merging this pull request may close these issues.

    Log when subscribers are notified
    2 participants