DEV Community: Paul

Logging steps in fca00c:Asteroids with a proxy contract

Paul — Thu, 30 Mar 2023 13:34:27 +0000

In the previous post we discussed how to implement a proxy contract for the game_engine to log solution-steps in fca00c:Asteroids. Now let's add a bit of flesh to it.

Recap

We have learned that in soroban

any client generated from a WASM can be used to interact with any other contract as long as the functions exist on both
when building a contract without debug-assertions the proxy still can be used for logging
- logging-capabilities are a bit limited due to the absence of std
- the code can be found on github

Adding actual logging to the existing `logging_engine`

Let's continue where we left off: https://github.com/hanseartic/fca00c-asteroids/tree/proxy_engine.

First thing we'd need to do is to record all the steps that are invoked on the game_engine. Ideally we'd only record actions that change the state of the game and skip the read-only operations.

For that we need to persist the actions:

fn log_action(env: &Env, action: &ActionItem) {
    let mut actions = Self::actions(env.clone());
    actions.push_back(*action);
    env.storage().set(&ACTIONS, &actions);
}

and call this function in every function that changes the game's state, e.g. like:

     pub fn p_turn(env: Env, direction: game_engine::Direction) -> Result<(), game_engine::Error> {
-        Ok(Self::get_engine(&env).p_turn(&direction))
+        if let Err(Ok(e)) = Self::get_engine(&env).try_p_turn(&direction) {
+            return Err(e);
+        }
+        Self::log_action(&env, &ActionItem(Action::Turn, direction as u32));
+        Ok(())
     }

Lets add this to all functions (see complete diff).

Printing the recorded actions in test

To see the recorded actions we need to print them in the test-case.

--- a/contracts/solution/src/test.rs
+++ b/contracts/solution/src/test.rs
@@ -40,9 +40,8 @@ fn fca00c_fast() {
     let env = Env::default();
     let proxy_engine_id = env.register_contract_wasm(None, logging_contract::WASM);
     let engine_id = env.register_contract_wasm(None, GameEngineWASM);
-    let engine = GameEngine::new(&env, &proxy_engine_id);
-
-    logging_contract::Client::new(&env, &proxy_engine_id).wrap(&engine_id);
+    let engine = logging_contract::Client::new(&env, &proxy_engine_id);
+    engine.wrap(&engine_id);

     // DON'T CHANGE THE FOLLOWING INIT() PARAMETERS
     // Once you've submitted your contract on the FCA00C site, we will invoke
Stage this hunk [y,n,q,a,d,j,J,g,/,e,?]? y
@@ -79,6 +78,12 @@ fn fca00c_fast() {
     let logs = env.logger().all();
     println!("{}", logs.join("\n"));

+    for action in engine.actions() {
+        if let Ok(a) = action {
+            println!("{:?}", a);
+        }
+    }
+
     let points = engine.p_points();

     println!("Points: {}", points);

🛈 as we might be adding more function to the log-contract it makes sense to use the logging_engine::Client for all invocations. The other way was just there to show the client does not actually matter as long as it implements a function present in the contract

and run the test again

❯ make test
cargo test fca00c_fast -- --nocapture
   Compiling soroban-asteroids-solution v0.0.0 (/home/paul/Code/fca00c - logging proxy/contracts/solution)
    Finished test [unoptimized + debuginfo] target(s) in 4.94s
     Running unittests src/lib.rs (target/debug/deps/soroban_asteroids_solution-5b0a3423b755223b)

running 1 test
invoker account is not configured
invoker account is not configured
🗒️ logger engine taking notes
ActionItem(Shoot, 1)
Points: 1
test test::fca00c_fast ... ok

test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 1 filtered out; finished in 0.56s
❯

👀 notice ActionItem(Shoot, 1) in the logs - that's us shooting and hitting one asteroid

Improving the output

We can rely on the debugging capabilities of println! macro or implement a slightly more fine-grained logging directly in the logging_engine. Let's for example add up all consecutive p_move calls and only record the last of multiple consecutive p_turn commands.

--- a/contracts/logging_engine/src/engine.rs
+++ b/contracts/logging_engine/src/engine.rs
@@ -30,7 +30,26 @@ impl LoggingEngine {
     }
     fn log_action(env: &Env, action: &ActionItem) {
         let mut actions = Self::actions(env.clone());
-        actions.push_back(*action);
+        let add_action: ActionItem;
+
+        if let Some(Ok(last_action_item)) = actions.last() {
+            match last_action_item {
+                ActionItem(Action::Turn, _) if action.0 == Action::Turn => {
+                    actions.pop_back();
+                    add_action = action.clone();
+                }
+                ActionItem(Action::Move, _) if action.0 == Action::Move => {
+                    actions.pop_back();
+                    add_action = ActionItem(last_action_item.0, last_action_item.1 + (action.1 as u32));
+
+                }
+                _ => add_action = *action,
+            }
+        } else {
+            add_action = *action;
+        }
+
+        actions.push_back(add_action);
         env.storage().set(&ACTIONS, &actions);
     }

🔔 don't forget to compile!

Now let's add some more calls to the game_engine in our solution:

--- a/contracts/solution/src/lib.rs
+++ b/contracts/solution/src/lib.rs
@@ -1,6 +1,6 @@
 #![no_std]

-use engine::Client as GameEngine;
+use engine::{Client as GameEngine, Direction};
 use soroban_sdk::{contractimpl, BytesN, Env};

 pub struct Solution;
@@ -19,6 +19,12 @@ impl Solution {
         // YOUR CODE START

         engine.p_shoot();
+        engine.p_move(&None);
+        engine.p_move(&Some(2));
+        engine.p_turn(&Direction::UpLeft);
+        engine.p_turn(&Direction::Left);
+        engine.p_move(&Some(1));
+        engine.p_turn(&Direction::Down);
         // YOUR CODE END
     }
 }

we would expect consecutive moves to be summed up as well as only the last of multiple consecutive turns to be logged

Let's take a look at the test-results:

🗒️ logger engine taking notes
ActionItem(Shoot, 1)
ActionItem(Move, 3)
ActionItem(Turn, 6)
ActionItem(Move, 1)
ActionItem(Turn, 4)
Points: 1

Looking good!

Check the diff of what we did here.

Customize the logs

Let's add a bit of color to the logs, shall we?
So let's have two options, one to be easily parseable (if you want to play back to steps) and one to be playful and nice to the human eye.

--- a/contracts/logging_engine/src/types.rs
+++ b/contracts/logging_engine/src/types.rs
@@ -1,4 +1,4 @@
-use soroban_sdk::{contracterror, contracttype};
+use soroban_sdk::{contracterror, contracttype, Env};

 #[contracterror]
 #[derive(Copy, Clone, Debug, Eq, PartialEq, PartialOrd)]
@@ -21,3 +21,15 @@ pub enum Action {
 #[contracttype]
 #[derive(Copy, Clone)]
 pub struct ActionItem(pub Action, pub u32);
+
+#[contracttype]
+#[derive(Copy, Clone, Debug, PartialEq)]
+pub enum LogLevel {
+    Quiet,
+    Human,
+    Machine,
+}
+
+pub trait LogFormat {
+    fn log_format(&self, env: &Env, level: &LogLevel);
+}

and define a trait how we expect logs to be called.

Now let's implement this

--- a/contracts/logging_engine/src/engine.rs
+++ b/contracts/logging_engine/src/engine.rs
@@ -1,5 +1,5 @@
 use soroban_sdk::{contractimpl, log, panic_with_error, vec, BytesN, Env, Map, Vec};
-use crate::types::{Action, ActionItem, ProxyError};
+use crate::types::{Action, ActionItem, LogFormat, LogLevel, ProxyError};

 mod game_engine {
     soroban_sdk::contractimport!(file = "../game_engine.wasm");
@@ -53,6 +53,42 @@ impl LoggingEngine {
         env.storage().set(&ACTIONS, &actions);
     }

+    pub fn get_logs(env: Env, level: LogLevel) {
+        log!(&env, "\n");
+        if LogLevel::Quiet == level {
+            log!(&env, "🤷 `LogLevel::Quiet` won't output any logs.");
+            return;
+        }
+        log!(&env, "📼 here are the recorded steps:\n");
+
+        log!(&env, "\n==< MEANING >==\n");
+        match level {
+            LogLevel::Human => {
+                log!(&env, "🧰: upgrade");
+                log!(&env, "🚶: move");
+                log!(&env, "⇔⇕: turning");
+                log!(&env, "🔫🎆[🎆[🎆]]: hit(s)");
+                log!(&env, "⛽: harvest");
+            }
+            LogLevel::Machine => {
+                log!(&env, "0: upgrade");
+                log!(&env, "1..3: hit");
+                log!(&env, "4: harvest");
+                log!(&env, "8..15: turning");
+                log!(&env, "16..: move");
+            }
+            _ => (),
+        };
+
+        log!(&env, "\n===< STEPS >===\n");
+        for a_i in Self::actions(env.clone()) {
+            if let Ok(a) = a_i {
+                a.log_format(&env, &level);
+            }
+        }
+        log!(&env, "\n===============\n");
+    }
+
     /// wrapping interface implemention
     pub fn init(
         env: Env,
@@ -134,3 +170,52 @@ impl LoggingEngine {
         Self::get_engine(&env).get_map()
     }
 }
+
+impl LogFormat for ActionItem {
+    fn log_format(&self, env: &Env, level: &LogLevel) {
+        match &self.0 {
+            Action::Harvest => match level {
+                LogLevel::Human => log!(&env, "⛽"),
+                LogLevel::Machine => log!(&env, "4"),
+                _ => (),
+            },
+            Action::Upgrade => match level {
+                LogLevel::Human => log!(&env, "🧰"),
+                LogLevel::Machine => log!(&env, "0"),
+                _ => (),
+            },
+            Action::Shoot => match level {
+                LogLevel::Human => {
+                    match self.1 {
+                        3 => log!(&env, "🔫🎆🎆🎆"),
+                        2 => log!(&env, "🔫🎆🎆"),
+                        1 => log!(&env, "🔫🎆"),
+                        _ => log!(&env, "🔫"),
+                    };
+                }
+                LogLevel::Machine => log!(&env, "{}", self.1 as u32),
+                _ => (),
+            },
+            Action::Move => match level {
+                LogLevel::Human => log!(&env, "🚶 {}", self.1),
+                LogLevel::Machine => log!(&env, "{}", self.1 as u32 + 15),
+                _ => (),
+            },
+            Action::Turn => match level {
+                LogLevel::Human => match self.1 {
+                    0 => log!(&env, "⇧"),
+                    1 => log!(&env, "⇗"),
+                    2 => log!(&env, "⇒"),
+                    3 => log!(&env, "⇘"),
+                    4 => log!(&env, "⇩"),
+                    5 => log!(&env, "⇙"),
+                    6 => log!(&env, "⇦"),
+                    7 => log!(&env, "⇖"),
+                    _ => (),
+                },
+                LogLevel::Machine => log!(&env, "{}", (self.1 as u32) + 8),
+                _ => (),
+            },
+        };
+    }
+}

We've just added a way to present the logs in different variations. Let's check back with the tests.

But first we of course need to a) compile the logging_engine and b) add a call to the newly added log-function:

--- a/contracts/solution/src/test.rs
+++ b/contracts/solution/src/test.rs
@@ -75,15 +75,13 @@ fn fca00c_fast() {

     solution.solve(&proxy_engine_id);

+    engine.get_logs(&logging_contract::LogLevel::Human);
+    engine.get_logs(&logging_contract::LogLevel::Machine);
+    engine.get_logs(&logging_contract::LogLevel::Quiet);
+
     let logs = env.logger().all();
     println!("{}", logs.join("\n"));

-    for action in engine.actions() {
-        if let Ok(a) = action {
-            println!("{:?}", a);
-        }
-    }
-
     let points = engine.p_points();

     println!("Points: {}", points);

Here we go:

🗒️ logger engine taking notes


📼 here are the recorded steps:


==< MEANING >==

🧰: upgrade
🚶: move
⇔⇕: turning
🔫🎆[🎆[🎆]]: hit(s)
⛽: harvest

===< STEPS >===

🔫🎆
🚶 U32(3)
⇦
🚶 U32(1)
⇩

===============



📼 here are the recorded steps:


==< MEANING >==

0: upgrade
1..3: hit
4: harvest
8..15: turning
16..: move

===< STEPS >===

U32(1)
U32(18)
U32(14)
U32(16)
U32(12)

===============



🤷 `LogLevel::Quiet` won't output any logs.
Points: 1

🎉 Congratulations! We've added nice looking, customizable logging to the challenge without bloating our solution!

Now you just need to solve the actual fca00c:Asteroids challenge - the all-time leaderboard is still open for submissions!!!

Drawbacks

As the u32 type is always rendered as U32(<VALUE>) numbers can't nicely be logged from soroban (yet).
To proxy another contract we'd need to implement the complete interface again. There is no generic proxying solution in soroban.

Implementing a proxy contract for the game_engine to log solution-steps in fca00c

Paul — Wed, 29 Mar 2023 22:08:26 +0000

To provide a hands on gamified approach to tinker with soroban, the latest series of Stellar Quest (fca00c: Asteroids) was all about submitting a compiled WASM to compete in three categories:

earliest working submission
smallest working submission
most efficient (CPU cycles) working submission

Optimizing the contract

Although soroban already offers pretty resource-oriented logging capabilites (e.g. strips everything related to logging from release builds), all the logic around making logs readable would still stay in the contract and bloat the file size.

So our approach here is to keep everything log-related out of the solution (that was supposed to be submitted) and use a proxy between the solution and the game-engine provided. To achieve that we can make use of a proxy that logs all the commands before invoking them on the actual engine.

A few things need to be considered here:

release builds (as described/configured per soroban docs) strip the log! macro related code
we want the proxy contract to always log - even if used by a release solution
as the proxy is another soroban contract, the same limitations regarding logging/formatting apply due to std not being available

For sake of context let's just add the contract next to the solution contract but keep it out of the workspace:

❯ tree contracts/ -L 2
contracts/
├── _game_engine
│   ├── engine.rs
│   ├── lib.rs
│   ├── map.rs
│   ├── storage.rs
│   └── types.rs
├── game_engine.wasm
├── logging_engine
│   ├── Cargo.lock
│   ├── Cargo.toml
│   └── src
└── solution
    ├── Cargo.toml
    └── src

5 directories, 9 files
❯

That way we can individually configure the contract to always build with debug-assertions = true but we don't need to deal with configuring this as a workspace package with profile-overrides.

Implementing the engine contract

First of all the original game_engine contract-interface needs to be implemented so that our logging_engine provides all the expected functions defined by the game_engine::Contract.

By using impl Contract for LoggingEngine the complete game_engine interface is enforced to be implemented.

contracts/logging_engine/src/engine.rs:
show file listing

use soroban_sdk::{contractimpl, Env, Map};
mod game_engine {
    soroban_sdk::contractimport!(file = "../game_engine.wasm");
}
use game_engine::Contract;

pub struct LoggingEngine;
#[contractimpl]
impl Contract for LoggingEngine {
    fn init(
        env: Env,
        move_step: u32,
        laser_range: u32,
        seed: u64,
        view_range: u32,
        fuel: (u32, u32, u32, u32),
        asteroid_reward: u32,
        asteroid_density: u32,
        pod_density: u32,
    ) {
        todo!("needs implementation")
    }
    fn p_turn(env: Env, direction: game_engine::Direction) -> Result<(), game_engine::Error> {
        todo!("needs implementation")
    }
    fn p_move(env: Env, times: Option<u32>) -> Result<(), game_engine::Error> {
        todo!("needs implementation")
    }
    fn p_shoot(env: Env) -> Result<(), game_engine::Error> {
        todo!("needs implementation")
    }
    fn p_harvest(env: Env) -> Result<(), game_engine::Error> {
        todo!("needs implementation")
    }
    fn p_upgrade(env: Env) -> Result<(), game_engine::Error> {
        todo!("needs implementation")
    }
    fn p_pos(env: Env) -> game_engine::Point {
        todo!("needs implementation")
    }
    fn p_dir(env: Env) -> game_engine::Direction {
        todo!("needs implementation")
    }
    fn p_points(env: Env) -> u32 {
        todo!("needs implementation")
    }
    fn p_fuel(env: Env) -> u32 {
        todo!("needs implementation")
    }
    fn get_map(env: Env) -> Map<game_engine::Point, game_engine::MapElement> {
        todo!("needs implementation")
    }
}

This can only be an intermediary step to make sure every function was implemented. Unfortunately only a single #[contractimpl] is possible per soroban contract.

As we want to augment the logging contract with at least one more function (we need to tell the proxy what to actually proxy, right?) we need to remove to impl Contract for because we can't add functions to an implementation that are not defined in the trait.

So let's compile the contract to make sure everything is in place:

❯ RUSTFLAGS="-A unused" \
  cargo build \
  --target wasm32-unknown-unknown \
  --release 
    Finished release [unoptimized + debuginfo] target(s) in 0.12s

❯

we are passing the RUSTFLAGS here once just to prevent ⚠️warnings⚠️ for all the unused variables

🎉 Great - it builds 🛠️

Proxying the `game_engine::Client`

Now let's add the actual proxying to the implementation.

First we need a way to call the proxied client. So let's add another function (wrap) that accepts the client-id.

@@ -1,13 +1,27 @@
-use soroban_sdk::{contractimpl, Env, Map};
+use soroban_sdk::{contractimpl, log, BytesN, Env, Map};
 mod game_engine {
     soroban_sdk::contractimport!(file = "../game_engine.wasm");
 }
-use game_engine::Contract;
+
+const ENGINE_ID: &str = "engine";

 pub struct LoggingEngine;
 #[contractimpl]
-impl Contract for LoggingEngine {
-    fn init(
+impl LoggingEngine {
+    pub fn wrap(env: Env, engine_id: BytesN<32>) {
+        env.storage().set(&ENGINE_ID, &engine_id);
+        log!(&env, "🗒️ logger engine taking notes");
+    }
+
+    fn engine_id(env: Env) -> BytesN<32> {
+        env.storage().get(&ENGINE_ID).unwrap().unwrap()
+    }
+    fn get_engine(env: &Env) -> game_engine::Client {
+        game_engine::Client::new(&env, &Self::engine_id(env.clone()))
+    }
+
+    /// wrapping interface implemention
+    pub fn init(
         env: Env,
         move_step: u32,
         laser_range: u32,

Additionally we'd add all the proxy-calls (see here for the full diff) and build again:

❯ cargo build --target wasm32-unknown-unknown --release 
   Compiling stellar-xdr v0.0.14
   Compiling static_assertions v1.1.0
   Compiling soroban-env-common v0.0.14
   Compiling soroban-env-guest v0.0.14
   Compiling soroban-sdk v0.6.0
   Compiling logging-engine v0.0.0 (/home/paul/Code/fca00c - logging proxy/contracts/logging_engine)
    Finished release [unoptimized + debuginfo] target(s) in 7.91s
❯

🎊 no ⚠️warning⚠️ anymore

🧩 Now let's put this thing together

Finally we want to see if/how this can be invoked in our test.

It's pretty easy: As both contracts implement the same interface we can even use the original game_engine::Client to invoke functions in the proxy (logging_engine).

To prove this is working let's just shoot the first asteroid (which is fortunately just ahead of the starting position):

--- a/contracts/solution/src/lib.rs
+++ b/contracts/solution/src/lib.rs
@@ -18,6 +18,7 @@ impl Solution {

         // YOUR CODE START

+        engine.p_shoot();
         // YOUR CODE END
     }
 }

and do this through the logging_engine:

--- a/contracts/solution/src/test.rs
+++ b/contracts/solution/src/test.rs
@@ -15,7 +15,7 @@
 /// cost will decrease as well.
 use std::println;

-use soroban_sdk::Env;
+use soroban_sdk::{testutils::Logger, Env};

 use crate::{
     engine::{Client as GameEngine, WASM as GameEngineWASM},
@@ -24,14 +24,25 @@ use crate::{

 extern crate std;

+mod logging_contract {
+    use crate::engine::{Direction, Error, MapElement, Point};
+
+    soroban_sdk::contractimport!(
+        file = "../logging_engine/target/wasm32-unknown-unknown/release/logging_engine.wasm"
+    );
+}
+
 /// ESPECIALLY LEAVE THESE TESTS ALONE
 #[test]
 fn fca00c_fast() {
     // Here we install and register the GameEngine contract in a default Soroban
     // environment, and build a client that can be used to invoke the contract.
     let env = Env::default();
+    let proxy_engine_id = env.register_contract_wasm(None, logging_contract::WASM);
     let engine_id = env.register_contract_wasm(None, GameEngineWASM);
-    let engine = GameEngine::new(&env, &engine_id);
+    let engine = GameEngine::new(&env, &proxy_engine_id);
+
+    logging_contract::Client::new(&env, &proxy_engine_id).wrap(&engine_id);

     // DON'T CHANGE THE FOLLOWING INIT() PARAMETERS
     // Once you've submitted your contract on the FCA00C site, we will invoke
@@ -63,12 +74,15 @@ fn fca00c_fast() {
     // We reset the budget so you have the best chance to not hit a TrapMemLimitExceeded or TrapCpuLimitExceeded error
     env.budget().reset();

-    solution.solve(&engine_id);
+    solution.solve(&proxy_engine_id);
+
+    let logs = env.logger().all();
+    println!("{}", logs.join("\n"));

     let points = engine.p_points();

     println!("Points: {}", points);
-    assert!(points >= 100);
+    assert!(points >= 1);
 }

 #[test]

❗note how the original GameClient is initialized just with the logging_engine's id❗

Now run the tests:

❯ make test
cargo test fca00c_fast -- --nocapture
   Compiling soroban-asteroids-solution v0.0.0 (/home/paul/Code/fca00c - logging proxy/contracts/solution)
    Finished test [unoptimized + debuginfo] target(s) in 5.05s
     Running unittests src/lib.rs (target/debug/deps/soroban_asteroids_solution-5b0a3423b755223b)

running 1 test
invoker account is not configured
invoker account is not configured
🗒️ logger engine taking notes
Points: 1
test test::fca00c_fast ... ok

test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 1 filtered out; finished in 0.44s

❯

🏁 Great, we've made a proxy contract that allows us to keep the solution clean and does not need us to tinker with the original game_engine either 👏!