test: real-deployment coverage for inner instruction events

.github/workflows/reusable-tests.yaml

@@ -184,6 +184,8 @@ jobs:
             name: optional.so
           - path: tests/events/
             name: events.so
+          - path: tests/events/
+            name: events_caller.so
           - path: examples/tutorial/basic-4/
             name: basic_4.so
           - path: examples/tutorial/basic-2/
@@ -236,6 +238,10 @@ jobs:
         with:
           name: events.so
           path: tests/events/target/deploy/
+      - uses: actions/download-artifact@d3f86a106a0bac45b974a628896c90dbdf5c8093 # v4
+        with:
+          name: events_caller.so
+          path: tests/events/target/deploy/
       - uses: actions/download-artifact@d3f86a106a0bac45b974a628896c90dbdf5c8093 # v4
         with:
           name: basic_4.so

client/example/Cargo.toml

@@ -16,6 +16,7 @@ basic-4 = { path = "../../examples/tutorial/basic-4/programs/basic-4", features
 composite = { path = "../../tests/composite/programs/composite", features = ["no-entrypoint"] }
 optional = { path = "../../tests/optional/programs/optional", features = ["no-entrypoint"] }
 events = { path = "../../tests/events/programs/events", features = ["no-entrypoint"] }
+events-caller = { path = "../../tests/events/programs/events-caller", features = ["no-entrypoint"] }
 anyhow = "1.0.32"
 clap = { version = "4.2.4", features = ["derive"] }
 shellexpand = "2.1.0"

client/example/run-test.sh

@@ -26,6 +26,7 @@ main() {
     local basic_2_pid="Fg6PaFpoGXkYsidMpWTK6W2BeZ7FEfcYkg476zPFsLnS"
     local basic_4_pid="CwrqeMj2U8tFr1Rhkgwc84tpAsqbt9pTt2a4taoTADPr"
     local events_pid="2dhGsWUzy5YKUsjZdLHLmkNpUDAXkNa9MYWsPc4Ziqzy"
+    local events_caller_pid="9Cjn1bYn2naaf4JCHSSEfMGcnUsLGSdKHpYX3wc6NvwU"
     local optional_pid="FNqz6pqLAwvMSds2FYjR4nKV3moVpPNtvkfGFrqLKrgG"
 
     cd ../../tests/composite && anchor build --skip-lint --ignore-keys && cd -
@@ -52,6 +53,7 @@ main() {
         --basic-2-pid $basic_2_pid \
         --basic-4-pid $basic_4_pid \
         --events-pid $events_pid \
+        --events-caller-pid $events_caller_pid \
         --optional-pid $optional_pid
 
     #
@@ -68,6 +70,7 @@ main() {
         --basic-2-pid $basic_2_pid \
         --basic-4-pid $basic_4_pid \
         --events-pid $events_pid \
+        --events-caller-pid $events_caller_pid \
         --optional-pid $optional_pid \
         --multithreaded
 
@@ -85,6 +88,7 @@ main() {
         --basic-2-pid $basic_2_pid \
         --basic-4-pid $basic_4_pid \
         --events-pid $events_pid \
+        --events-caller-pid $events_caller_pid \
         --optional-pid $optional_pid \
         --multithreaded
 
@@ -143,6 +147,7 @@ start_surfpool() {
         --input basic_2_pid=$basic_2_pid \
         --input basic_4_pid=$basic_4_pid \
         --input events_pid=$events_pid \
+        --input events_caller_pid=$events_caller_pid \
         --input optional_pid=$optional_pid \
         >&2
 

client/example/setup.tx

@@ -32,6 +32,11 @@ action "setup" "svm::setup_surfnet" {
         binary_path = "../../tests/events/target/deploy/events.so"
         authority = signer.authority.public_key
     }
+    deploy_program {
+        program_id = input.events_caller_pid
+        binary_path = "../../tests/events/target/deploy/events_caller.so"
+        authority = signer.authority.public_key
+    }
     deploy_program {
         program_id = input.optional_pid
         binary_path = "../../tests/optional/target/deploy/optional.so"

client/example/src/blocking.rs

@@ -11,7 +11,9 @@ use basic_2::accounts as basic_2_accounts;
 use basic_2::instruction as basic_2_instruction;
 use basic_2::Counter;
 use events::instruction as events_instruction;
-use events::MyEvent;
+use events::{MyEvent, MyOtherEvent};
+use events_caller::accounts as events_caller_accounts;
+use events_caller::instruction as events_caller_instruction;
 use optional::accounts::Initialize as OptionalInitialize;
 use optional::instruction as optional_instruction;
 // The `accounts` and `instructions` modules are generated by the framework.
@@ -59,6 +61,7 @@ pub fn main() -> Result<()> {
         let payer: &Keypair = &payer;
         let client = Client::new_with_options(url, payer, CommitmentConfig::processed());
         events(&client, opts.events_pid)?;
+        events_cpi(&client, opts.events_caller_pid, opts.events_pid)?;
         optional(&client, opts.optional_pid)?;
     } else {
         // Client.
@@ -81,6 +84,11 @@ pub fn main() -> Result<()> {
             let local_client = Arc::clone(&client);
             handles.push(std::thread::spawn(move || test(&local_client, arg)));
         }
+        let local_client = Arc::clone(&client);
+        let (events_caller_pid, events_pid) = (opts.events_caller_pid, opts.events_pid);
+        handles.push(std::thread::spawn(move || {
+            events_cpi(&local_client, events_caller_pid, events_pid)
+        }));
         for handle in handles {
             assert!(handle.join().unwrap().is_ok());
         }
@@ -230,6 +238,45 @@ pub fn events<C: Deref<Target = impl Signer> + Clone>(
     Ok(())
 }
 
+// Tests that events emitted by inner instructions (CPI, invoke depth >= 2)
+// are detected when subscribed to the emitting program. Regression test for
+// the log parsing fix in #4451 against a real deployment (#4656).
+pub fn events_cpi<C: Deref<Target = impl Signer> + Clone>(
+    client: &Client<C>,
+    caller_pid: Pubkey,
+    events_pid: Pubkey,
+) -> Result<()> {
+    let events_program = client.program(events_pid)?;
+    let caller_program = client.program(caller_pid)?;
+
+    let (sender, receiver) = std::sync::mpsc::channel();
+    let event_unsubscriber = events_program.on(move |_, event: MyOtherEvent| {
+        if sender.send(event).is_err() {
+            println!("Error while transferring the event.")
+        }
+    })?;
+
+    sleep(Duration::from_millis(1000));
+
+    caller_program
+        .request()
+        .accounts(events_caller_accounts::CpiEvent {
+            events_program: events_pid,
+        })
+        .args(events_caller_instruction::CpiEvent {})
+        .send()?;
+
+    let event = receiver.recv().unwrap();
+    assert_eq!(event.data, 6);
+    assert_eq!(event.label, "bye".to_string());
+
+    event_unsubscriber.unsubscribe();
+
+    println!("Events CPI success!");
+
+    Ok(())
+}
+
 pub fn basic_4<C: Deref<Target = impl Signer> + Clone>(
     client: &Client<C>,
     pid: Pubkey,

client/example/src/main.rs

@@ -19,6 +19,8 @@ pub struct Opts {
     #[clap(long)]
     events_pid: Pubkey,
     #[clap(long)]
+    events_caller_pid: Pubkey,
+    #[clap(long)]
     optional_pid: Pubkey,
     #[clap(long, default_value = "false")]
     multithreaded: bool,

client/example/src/nonblocking.rs

@@ -11,7 +11,9 @@ use basic_2::accounts as basic_2_accounts;
 use basic_2::instruction as basic_2_instruction;
 use basic_2::Counter;
 use events::instruction as events_instruction;
-use events::MyEvent;
+use events::{MyEvent, MyOtherEvent};
+use events_caller::accounts as events_caller_accounts;
+use events_caller::instruction as events_caller_instruction;
 use optional::accounts::Initialize as OptionalInitialize;
 use optional::instruction as optional_instruction;
 // The `accounts` and `instructions` modules are generated by the framework.
@@ -56,6 +58,7 @@ pub async fn main() -> Result<()> {
     let payer: &Keypair = &payer;
     let client = Client::new_with_options(url, payer, CommitmentConfig::processed());
     events(&client, opts.events_pid).await?;
+    events_cpi(&client, opts.events_caller_pid, opts.events_pid).await?;
     optional(&client, opts.optional_pid).await?;
     // Success.
     Ok(())
@@ -243,6 +246,48 @@ pub async fn events<C: Deref<Target = impl Signer> + Clone>(
     Ok(())
 }
 
+// Tests that events emitted by inner instructions (CPI, invoke depth >= 2)
+// are detected when subscribed to the emitting program. Regression test for
+// the log parsing fix in #4451 against a real deployment (#4656).
+pub async fn events_cpi<C: Deref<Target = impl Signer> + Clone>(
+    client: &Client<C>,
+    caller_pid: Pubkey,
+    events_pid: Pubkey,
+) -> Result<()> {
+    let events_program = client.program(events_pid)?;
+    let caller_program = client.program(caller_pid)?;
+
+    let (sender, mut receiver) = mpsc::unbounded_channel();
+    let event_unsubscriber = events_program
+        .on(move |_, event: MyOtherEvent| {
+            if sender.send(event).is_err() {
+                println!("Error while transferring the event.")
+            }
+        })
+        .await?;
+
+    sleep(Duration::from_millis(1000)).await;
+
+    caller_program
+        .request()
+        .accounts(events_caller_accounts::CpiEvent {
+            events_program: events_pid,
+        })
+        .args(events_caller_instruction::CpiEvent {})
+        .send()
+        .await?;
+
+    let event = receiver.recv().await.unwrap();
+    assert_eq!(event.data, 6);
+    assert_eq!(event.label, "bye".to_string());
+
+    event_unsubscriber.unsubscribe().await;
+
+    println!("Events CPI success!");
+
+    Ok(())
+}
+
 pub async fn basic_4<C: Deref<Target = impl Signer> + Clone>(
     client: &Client<C>,
     pid: Pubkey,

tests/events/Anchor.toml

@@ -4,6 +4,7 @@ wallet = "~/.config/solana/id.json"
 
 [programs.localnet]
 events = "2dhGsWUzy5YKUsjZdLHLmkNpUDAXkNa9MYWsPc4Ziqzy"
+events_caller = "9Cjn1bYn2naaf4JCHSSEfMGcnUsLGSdKHpYX3wc6NvwU"
 
 [scripts]
 test = "yarn run ts-mocha -t 1000000 -p ./tsconfig.json tests/**/*.ts"

tests/events/programs/events-caller/Cargo.toml

@@ -0,0 +1,19 @@
+[package]
+name = "events-caller"
+version = "0.1.0"
+description = "Created with Anchor"
+edition = "2021"
+
+[lib]
+crate-type = ["cdylib", "lib"]
+name = "events_caller"
+
+[features]
+no-entrypoint = []
+cpi = ["no-entrypoint"]
+default = []
+idl-build = ["anchor-lang/idl-build"]
+
+[dependencies]
+anchor-lang = { path = "../../../../lang" }
+events = { path = "../events", features = ["no-entrypoint"] }

tests/events/programs/events-caller/src/lib.rs

@@ -0,0 +1,33 @@
+//! This program CPIs into the `events` program so that events are
+//! emitted from an inner instruction (invoke depth >= 2). Clients
+//! subscribed to the `events` program must still detect them, which
+//! is the scenario from #4450 fixed in #4451.
+
+use anchor_lang::{
+    prelude::*,
+    solana_program::{instruction::Instruction, program::invoke},
+    InstructionData,
+};
+use events::program::Events;
+
+declare_id!("9Cjn1bYn2naaf4JCHSSEfMGcnUsLGSdKHpYX3wc6NvwU");
+
+#[program]
+pub mod events_caller {
+    use super::*;
+
+    pub fn cpi_event(ctx: Context<CpiEvent>) -> Result<()> {
+        let ix = Instruction {
+            program_id: ctx.accounts.events_program.key(),
+            accounts: vec![],
+            data: events::instruction::TestEvent.data(),
+        };
+        invoke(&ix, &[ctx.accounts.events_program.to_account_info()])?;
+        Ok(())
+    }
+}
+
+#[derive(Accounts)]
+pub struct CpiEvent<'info> {
+    pub events_program: Program<'info, Events>,
+}

tests/events/tests/events.ts

@@ -2,11 +2,14 @@ import * as anchor from "@anchor-lang/core";
 import { assert } from "chai";
 
 import { Events } from "../target/types/events";
+import { EventsCaller } from "../target/types/events_caller";
 
 describe("Events", () => {
   // Configure the client to use the local cluster.
   anchor.setProvider(anchor.AnchorProvider.env());
   const program = anchor.workspace.Events as anchor.Program<Events>;
+  const eventsCaller = anchor.workspace
+    .EventsCaller as anchor.Program<EventsCaller>;
   const confirmOptions: anchor.web3.ConfirmOptions = {
     commitment: "confirmed",
     preflightCommitment: "confirmed",
@@ -119,4 +122,53 @@ describe("Events", () => {
       throw new Error("Was able to invoke the self-CPI instruction");
     });
   });
+
+  // The `events-caller` program CPIs into the `events` program, so the
+  // event is emitted from an inner instruction (invoke depth 2). These
+  // tests verify the log parsing fix from #4451 against a real
+  // deployment instead of synthetic log data (#4656, #4450).
+  describe("Inner instruction event", () => {
+    it("Is delivered to event listeners", async () => {
+      let listenerId: number;
+      const eventPromise = new Promise<Event["myOtherEvent"]>((res) => {
+        listenerId = program.addEventListener("myOtherEvent", (event) => {
+          res(event);
+        });
+      });
+      // Give the log subscription time to become active before sending
+      // the transaction, otherwise the only emission can be missed.
+      await new Promise((res) => setTimeout(res, 500));
+      await eventsCaller.methods
+        .cpiEvent()
+        .accounts({ eventsProgram: program.programId })
+        .rpc(confirmOptions);
+      const event = await eventPromise;
+      await program.removeEventListener(listenerId);
+
+      assert.strictEqual(event.data.toNumber(), 6);
+      assert.strictEqual(event.label, "bye");
+    });
+
+    it("Is detected by the event parser in on-chain transaction logs", async () => {
+      const txHash = await eventsCaller.methods
+        .cpiEvent()
+        .accounts({ eventsProgram: program.programId })
+        .rpc(confirmOptions);
+      const txResult = await program.provider.connection.getTransaction(
+        txHash,
+        {
+          commitment: "confirmed",
+          maxSupportedTransactionVersion: 0,
+        }
+      );
+
+      const parser = new anchor.EventParser(program.programId, program.coder);
+      const events = [...parser.parseLogs(txResult.meta.logMessages)];
+
+      assert.strictEqual(events.length, 1);
+      assert.strictEqual(events[0].name, "myOtherEvent");
+      assert.strictEqual(events[0].data.label, "bye");
+      assert.strictEqual((events[0].data.data as anchor.BN).toNumber(), 6);
+    });
+  });
 });