PocketIC HttpGateway update calls not processing

Developers
1

Maybe I am missing something fundamental about pocket-ic or the http gateway functionality but I am struggling to figure out how to get an update call to process (queries are fine) using the HttpGateway functionality in pocket-ic

Here is an example that I am running that uses the counter wasm canister and calls ‘inc’, but on that call it waits indefinately because there is no request_status for the request in the state
I tried to play around with time/ticks with manually setting and doing auto_progress but have had no luck

byte[] wasmModule = File.ReadAllBytes("CanisterWasmModules/counter.wasm");
CandidArg arg = CandidArg.FromCandid();


SubnetConfig nnsSubnet = SubnetConfig.New(); // NNS subnet required for HttpGateway

await using (PocketIc pocketIc = await PocketIc.CreateAsync(this.url, nnsSubnet: nnsSubnet))
{
	Principal canisterId = await pocketIc.CreateAndInstallCanisterAsync(wasmModule, arg);

	await pocketIc.StartCanisterAsync(canisterId);

	// Let time progress so that update calls get processed
	await using (await pocketIc.AutoProgressTimeAsync())
	{
		await using (HttpGateway httpGateway = await pocketIc.RunHttpGatewayAsync())
		{
			HttpAgent agent = httpGateway.BuildHttpAgent();
			QueryResponse getResponse = await agent.QueryAsync(canisterId, "get", CandidArg.Empty());
			CandidArg getResponseArg = getResponse.ThrowOrGetReply();
			UnboundedUInt getResponseValue = getResponseArg.ToObjects<UnboundedUInt>();
			Assert.Equal((UnboundedUInt)0, getResponseValue);


			CandidArg incResponseArg = await agent.CallAndWaitAsync(canisterId, "inc", CandidArg.Empty()); // Waits indefinately here
			Assert.Equal(CandidArg.Empty(), incResponseArg);

			// This alternative also doesnt work
			// RequestId requestId = await agent.CallAsync(canisterId, "inc", CandidArg.Empty());
			// ICTimestamp currentTime = await pocketIc.GetTimeAsync();
			// await pocketIc.SetTimeAsync(currentTime + TimeSpan.FromSeconds(5));
			// await pocketIc.TickAsync(5);
			// CandidArg incResponseArg = await agent.WaitForRequestAsync(canisterId, requestId);
			// Assert.Equal(CandidArg.Empty(), incResponseArg);

			getResponse = await agent.QueryAsync(canisterId, "get", CandidArg.Empty());
			getResponseArg = getResponse.ThrowOrGetReply();
			getResponseValue = getResponseArg.ToObjects<UnboundedUInt>();
			Assert.Equal((UnboundedUInt)1, getResponseValue);

			CandidArg setRequestArg = CandidArg.FromObjects((UnboundedUInt)10);
			CandidArg setResponseArg = await agent.CallAndWaitAsync(canisterId, "set", setRequestArg);
			Assert.Equal(CandidArg.Empty(), setResponseArg);

			getResponse = await agent.QueryAsync(canisterId, "get", CandidArg.Empty());
			getResponseArg = getResponse.ThrowOrGetReply();
			getResponseValue = getResponseArg.ToObjects<UnboundedUInt>();
			Assert.Equal((UnboundedUInt)10, getResponseValue);

		}
	}
}

I am currently implementing a .NET client for pocket-ic, so there is a good chance there is a bug on my end but I am kinda stuck and could use some direction. Any help would be appreciated

2

Here is a Rust test with a counter canister: I’d recommend you to follow what this test does.

3

That test isn’t http gateway specific and the other http gateway tests, i dont see anything relevant to what im trying to do with update call + http gateway

I see more relevant things in the pocket_ic_server tests like

but dont see any update call processing unfortunately

4

This test performs an update call against an HTTP gateway in PocketIC.

1 Like
5

Thanks for the example but im still struggling to find the issue
Any advice on how i should be debugging this?
Something I can see on the server end?
What makes/doesn’t make the update calls get processed via http gateway?

I am doing the same setup for the canister as direct calls for the http gateway calls, but only the http gateway blocks/hangs on processing the update calls

This is the only runtime/error logs i get from the server:

2
Nov 25 18:51:52.219 WARN s:/n:/ic_state_manager/ic_state_manager No state available with certification.
Nov 25 18:51:52.220 WARN s:/n:/ic_query_stats/payload_builder Current stats are uninitalized. This warning should go away after some minutes if the replica is processing query calls.
Nov 25 18:51:52.221 WARN s:/n:/ic_query_stats/payload_builder Current stats are uninitalized. This warning should go away after some minutes if the replica is processing query calls.

Any help or guidance would be amazing.
Thanks

6

you can export RUST_LOG=trace (environment variable) before starting the PocketIC server: this is gonna produce much more debug logs

7

Looks like its getting the request, then just sits there till it times out.
Same thing for a v2 call

Not sure what im looking for

2024-11-25T19:29:22.853556Z TRACE hyper_util::client::legacy::pool: checkout waiting for idle connection: ("http", localhost:40965)
2024-11-25T19:29:22.853582Z TRACE hyper_util::client::legacy::connect::http: Http::connect; scheme=Some("http"), host=Some("localhost"), port=Some(Port(40965))
2024-11-25T19:29:22.853746Z DEBUG hyper_util::client::legacy::connect::http: connecting to 127.0.0.1:40965
2024-11-25T19:29:22.853819Z DEBUG hyper_util::client::legacy::connect::http: connected to 127.0.0.1:40965
2024-11-25T19:29:22.853840Z TRACE hyper_util::client::legacy::client: http1 handshake complete, spawning background dispatcher task
2024-11-25T19:29:22.853852Z TRACE hyper_util::client::legacy::pool: checkout dropped for ("http", localhost:40965)
2024-11-25T19:29:22.854598Z DEBUG request{method=POST uri=/instances/0/api/v3/canister/7tjcv-pp777-77776-qaaaa-cai/call version=HTTP/1.1}: tower_http::trace::on_request: started processing request
2024-11-25T19:29:22.855058Z TRACE request{method=POST uri=/instances/0/api/v3/canister/7tjcv-pp777-77776-qaaaa-cai/call version=HTTP/1.1}: pocket_ic_server::state_api::state: update_with_timeout::start instance_id=0 op_id=call(7tjcv-pp777-77776-qaaaa-cai,Digest(508B857766D4749C4C60F494156AE9D3122D5DB0D4DD3656CA33C0C20CD79E99))
2024-11-25T19:29:22.855092Z TRACE pocket_ic_server::state_api::state: bg_task::start instance_id=0 state_label=StateLabel(07000000000000000000000000000000) op_id=call(7tjcv-pp777-77776-qaaaa-cai,Digest(508B857766D4749C4C60F494156AE9D3122D5DB0D4DD3656CA33C0C20CD79E99))
2024-11-25T19:29:22.855636Z TRACE pocket_ic_server::state_api::state: bg_task::end instance_id=0 op_id=call(7tjcv-pp777-77776-qaaaa-cai,Digest(508B857766D4749C4C60F494156AE9D3122D5DB0D4DD3656CA33C0C20CD79E99))
2024-11-25T19:29:22.855677Z TRACE request{method=POST uri=/instances/0/api/v3/canister/7tjcv-pp777-77776-qaaaa-cai/call version=HTTP/1.1}: pocket_ic_server::state_api::state: update_with_timeout::synchronous instance_id=0 op_id=call(7tjcv-pp777-77776-qaaaa-cai,Digest(508B857766D4749C4C60F494156AE9D3122D5DB0D4DD3656CA33C0C20CD79E99))
2024-11-25T19:29:22.862820Z TRACE pocket_ic_server::state_api::state: update_with_timeout::start instance_id=0 op_id=advance_time_and_tick(103.60742ms)
2024-11-25T19:29:22.862884Z TRACE pocket_ic_server::state_api::state: bg_task::start instance_id=0 state_label=StateLabel(08000000000000000000000000000000) op_id=advance_time_and_tick(103.60742ms)
2024-11-25T19:29:22.865432Z TRACE pocket_ic_server::state_api::state: bg_task::end instance_id=0 op_id=advance_time_and_tick(103.60742ms)
2024-11-25T19:29:22.865509Z TRACE pocket_ic_server::state_api::state: update_with_timeout::synchronous instance_id=0 op_id=advance_time_and_tick(103.60742ms)
2024-11-25T19:29:22.865517Z TRACE pocket_ic_server::state_api::state: update_with_timeout::start instance_id=0 op_id=process_canister_http_internal
2024-11-25T19:29:22.865545Z TRACE pocket_ic_server::state_api::state: bg_task::start instance_id=0 state_label=StateLabel(09000000000000000000000000000000) op_id=process_canister_http_internal
...
repeats advance_time_and_tick + process_canister_http_internal
8

This log line means that the HTTP request to /instances/0/api/v3/canister/7tjcv-pp777-77776-qaaaa-cai/call finished and returned a response: this response has the form specified here. So I’m not sure what you mean by “just sits there till it times out”.

9

The update http request times out with V3 and i don’t get a completed response for V2. Query requests are just fine though
Could the pocketic server finish the uodate, but the http gateway fail to respond?

10

I don’t think so and you could try to confirm by making an update call using dfx passing the HTTP gateway URL as --network to dfx.

11

Tried that with confusing results

When i do dfx canister call to it without --async i get a weird message that the cert is stale over 240s, which doesn’t seem to make sense because I have confirmed my times are in sync and i dont wait that long
BUT
I am able to do --async, get a ‘Request Id’ back, then try to wait on that response. It gives the same results of getting a ‘request status’ type of null indefinately. no ‘received’, ‘processing’, etc…, as i do with doing it with code (vs CLI)

  1. Does this mean that the request can’t be found?
  2. I currently DO have ‘auto progress’ or manual time inc running for this in my code, but does the request need time to progress to finish? (that being said, it seems like from the logs its finishing)

I feel decently confident that my client code for these http requests is good because that code has existed for a while (using both v2 and v3), it seems like im just having an issue getting the request to appear in the http gateway or something

Thanks for your help in this BTW

New code for reference

var processInfo = new ProcessStartInfo
{
	FileName = "dfx",
	Arguments = $"canister call {canisterId} inc () --network {httpGateway.Url} --identity anonymous --verbose --async",
	RedirectStandardOutput = true,
	RedirectStandardError = true,
	UseShellExecute = false,
	CreateNoWindow = true,
	WorkingDirectory = "/home/gekctek/git/ICP.NET",
};
Debug.WriteLine("dfx " + processInfo.Arguments);
RequestId requestId;
using (var process = Process.Start(processInfo))
{
	string output = process!.StandardOutput.ReadToEnd();
	string error = process.StandardError.ReadToEnd();
	process.WaitForExit();

	Debug.WriteLine($"Output: {output}");
	Debug.WriteLine($"Error: {error}");
	requestId = new RequestId(Convert.FromHexString(output.Trim().Substring(2)));
}
Debug.WriteLine("---Start-----\n\n\n\n\n\n\n\n\n\n\n");
CancellationTokenSource cts = new(TimeSpan.FromSeconds(5));

CandidArg incResponseArg = await agent.WaitForRequestAsync(canisterId, requestId, cts.Token); // Waits indefinitely here
Assert.Equal(CandidArg.Empty(), incResponseArg);
12

How did you confirm? And how do you set up the PocketIC server?

13

Well i confirmed that my computer time is the same on wsl, Windows and real time. I guess i don’t know how pocketic time works

Pocket ic server is setup in code and is created right before the test runs, then shuts down

public static async Task<PocketIcServer> Start(
			LogLevel? runtimeLogLevel = null,
			bool showErrorLogs = true
		)
		{
			string binPath = GetBinPath();
			EnsureExecutablePermission(binPath);

			int pid = Process.GetCurrentProcess().Id;
			string picFilePrefix = $"pocket_ic_{pid}";
			string portFilePath = Path.Combine(Path.GetTempPath(), $"{picFilePrefix}.port");

			var startInfo = new ProcessStartInfo
			{
				FileName = binPath,
				Arguments = $"--port-file {portFilePath}",
				RedirectStandardOutput = runtimeLogLevel != null,
				RedirectStandardError = showErrorLogs,
				UseShellExecute = false
			};
			if (runtimeLogLevel != null)
			{
				startInfo.EnvironmentVariables["RUST_LOG"] = runtimeLogLevel.Value.ToString().ToLower();
			}

			Process? serverProcess = Process.Start(startInfo);
14

How do you create an instance, set its time, and trigger auto-progress?

15

Im not sure what you are looking for with ‘create an instance’. I start the server as shown before, then use the api to create an instance with my created client method

Task<(int Id, List<SubnetTopology> Topology)> CreateInstanceAsync(
		List<SubnetConfig>? applicationSubnets = null,
		SubnetConfig? bitcoinSubnet = null,
		SubnetConfig? fiduciarySubnet = null,
		SubnetConfig? iiSubnet = null,
		SubnetConfig? nnsSubnet = null,
		SubnetConfig? snsSubnet = null,
		List<SubnetConfig>? systemSubnets = null,
		List<SubnetConfig>? verifiedApplicationSubnets = null,
		bool nonmainnetFeatures = false
	);

Then this is how it is run.
I never set the time, but I am trying now with no change


			await using (PocketIc pocketIc = await PocketIc.CreateAsync(this.url, nnsSubnet: nnsSubnet))
			{
				Principal canisterId = await pocketIc.CreateAndInstallCanisterAsync(wasmModule, arg);

				await pocketIc.StartCanisterAsync(canisterId);

				await pocketIc.SetTimeAsync(ICTimestamp.Now()); // Just added. Set time?
				// Let time progress so that update calls get processed
				await using (await pocketIc.AutoProgressTimeAsync())
				{
					await using (HttpGateway httpGateway = await pocketIc.RunHttpGatewayAsync())
					{

Here is a link to the example code that I am trying

16

Maybe if I better understood some of these concepts or what is required/different about the HttpGateway vs just a direct pocketic call
Remember that the direct pocketic calls work, its just the HttpGateway
Is there a way to set the time or something with the HttpGateway and that is throwing it off and rejecting requests/responses? Because it doesnt seem like it recognizes the request id for some reason

17

Could you please try again with dfx now that you set the time to the current timestamp?

what is required/different about the HttpGateway vs just a direct pocketic call

if you make an update call via the HTTP gateway, then you need to set all required fields according to the Interface Specification including authentication envelope and satisfying certain properties (valid signatures, ingress expiry not in the past and not more than 5 minutes into the future w.r.t. both current time and PocketIC time - this might be unsatisfiable if the PocketIC time is much off the current time) whereas if you make an update call via the path /instances/0/update/execute_ingress_message, then stuff like signatures and ingress expiry can be omitted.

18

I could reproduce the issue with dfx if I only call auto_progress without setting time to the current time explicitly before. I’ll try to make PocketIC fail with a helpful error message in this case.

19

Ok, so if i do:

  • dfx call WITH --async, i get a request id back, but cant get the status via code
  • dfx call WITHOUT --async, i now DOES work, and I can do a follow-up query call and see that ‘inc’ was executed
  • V3 Code call, i get back an ‘accepted’ response, then i have to poll for the request, which it then times out (note: never had a time sync error with the code, this how it always responded)
  • V2 Code call, it just polls with a null ‘request type’ until it times out

Inspecting the http call, it sends all the proper information, including an up to date ingress_expiry

image
image520×136 6.19 KB

And signatures (in another wrapper class)

But again, this Http Client has been around for a while and haven’t had any issues with it

I dont need you to debug or figure out whats wrong with my code. Im just trying to figure out the situation in which the Http Gateway would not show a request being processed, or how i could check anything on the http gateway side of things to understand if my code is doing something incorrect. If this was an issue with the time sync/spec issue it should be fixed and/or i should see some sort of error response, but its just not there like its not being processed, even though we saw some activity in the logs

20

UPDATE

Tick
need to tick, then it will process. Not sure why dfx it would work without a tick though
But also the timestamp seems to have been an issue

BUT the only way i could get it to work is

  1. Call ‘inc’ async
  2. Call Tick for pocketic
  3. Wait for request to complete

So im not sure how to do a call+wait call if I dont call tick in between
Does auto_progress just advance time or does it also tick?