ts: Program upgrade event crashes existing listeners

[dfl-zeke]

So, we have custom event inside our program and appropriate listener in our client. Problem is that when we upgrade our program (or run anchor test) our client program crashes and gives us following error:

/Users/zeke/WebstormProjects/marketplace-server/node_modules/@project-serum/anchor/src/program/event.ts:266
      throw new Error(`Could not find program invocation log line`);
            ^
Error: Could not find program invocation log line
    at new ExecutionContext (/Users/zeke/WebstormProjects/marketplace-server/node_modules/@project-serum/anchor/src/program/event.ts:266:13)
    at EventParser.parseLogs (/Users/zeke/WebstormProjects/marketplace-server/node_modules/@project-serum/anchor/src/program/event.ts:177:23)
    at Object.callback (/Users/zeke/WebstormProjects/marketplace-server/node_modules/@project-serum/anchor/src/program/event.ts:103:27)
    at Connection._wsOnLogsNotification (/Users/zeke/WebstormProjects/marketplace-server/node_modules/@solana/web3.js/src/connection.ts:4360:13)
    at Client.emit (/Users/zeke/WebstormProjects/marketplace-server/node_modules/eventemitter3/index.js:181:35)
    at /Users/zeke/WebstormProjects/marketplace-server/node_modules/rpc-websockets/dist/lib/client.js:446:22
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
error Command failed with exit code 1.

So when we upgrade program, following regex fails /^Program (.*) invoke.*$/g, because log starts with: Upgraded program **** and causes our client to crash.

Class name is ExecutionContext where this regex is used. We can fix it by simply wrapping creation of this class in try/catch, but there could be better solutions, because we don't want to change it inside node_modules

Our client code:

 program.addEventListener("ListingClosed", (event: ListingClosedEvent) => {
        console.log('event', event.accountAddress.toBase58())
 });

[dfl-zeke]

@paul-schaaf I think this should be considered as a bug, because it crashes whole program and you can't catch this exception. Also, I can make PR if it's okay.

[dfl-zeke]

Created pull request #1730

[paul-schaaf]

Could you post the logs that you received or a minimal reproducibl example?

[dfl-zeke]

Could you post the logs that you received or a minimal reproducibl example?

Yes, of course. I've added tests for it in the pull request, but will copy it here:

it("Program Upgrade Event", () => {
    const logs = [
      "Upgraded program J2XMGdW2qQLx7rAdwWtSZpTXDgAQ988BLP9QTgUZvm54",
    ];

    const idl = {
      version: "0.0.0",
      name: "basic_1",
      instructions: [
        {
          name: "initialize",
          accounts: [],
          args: [],
        },
      ],
    };

    const coder = new BorshCoder(idl);
    const programId = PublicKey.default;
    const eventParser = new EventParser(programId, coder);

    eventParser.parseLogs(logs, (event) => {
      expect(event.name).toEqual("$error");
      expect(event.data).toEqual("Could not find program invocation log line");
    });
  });

The log that get's printed after program upgrade is: Upgraded program J2XMGdW2qQLx7rAdwWtSZpTXDgAQ988BLP9QTgUZvm54

Edit:

Also, I think node program should not crash if some unexpected log got somehow in the events log, that's why I thought handling it outside was better idea.

[paul-schaaf]

So after you upgrade a program, all logs start with Upgraded program instead of Program?

[paul-schaaf]

So after you upgrade a program, all logs start with Upgraded program instead of Program?

am looking at the solana core code. That doesnt seem to happen.

So looks like I am misunderstanding. Could you provide a program or describe a flow so I can build one so I can run it myself to get that error?

[dfl-grisha]

So after you upgrade a program, all logs start with Upgraded program instead of Program?

Hello,
Yes, this unusual behaviour happens only on program upgrades and deployments. But it seems only one log line starts with Upgraded Program.

Here you can view two such transactions:

1. program upgrade transaction
2. program creation transaction

It happens on upgrade of any program.
steps to reproduce in terminal:

• anchor init some-name

• cd some-name

• anchor deploy. # this transaction emits log starting with Deployed program ...

• anchor upgrade --program-id # this one has only one log line starting with Upgraded program

@paul-schaaf Do you think it's better to change regExp for log-parsing to also handle these types of events in client library?

[paul-schaaf]

@dfl-grisha yes the library should be handle to handle all solana logs. It should never error

[dfl-grisha]

@dfl-grisha yes the library should be handle to handle all solana logs. It should never error

Should we fire some custom event when program upgrade occurs?
The client can only be subscribed to user created custom events right now. Should clients be able to subscribe to program upgrades or we should just skip them?

[dfl-grisha]

Also right now event parser assumes that the first line of transaction logs starts with the prefix Program Invoke, but as it turns out that is not always the case.

[dfl-zeke]

@paul-schaaf If this solution is okay, I will make PR. We just removed constructor of ExecutionContext, because we don't need to make sure that log starts with Program Invoke, it can start with Upgraded program and maybe in the future, with something else...

We've added tests to make sure, that it works as intended.

[dfl-grisha]

hello @armaniferrante,
maybe you can share some thoughts about Zeke's idea above?

[paul-schaaf]

@dfl-zeke yes that solution looks good to me. It would be great if you could add another test that just checks the normal case where there the logs dont start with "Upgraded Program".

[dfl-zeke]

@dfl-zeke yes that solution looks good to me. It would be great if you could add another test that just checks the normal case where there the logs dont start with "Upgraded Program".

Yes, sure! I'll add more tests and do PR!