Logging steps in fca00c:Asteroids with a proxy contract
Tags: soroban, sorobanathon, stellar, fca00c
Published: 2023-03-30 13:34:27

In the [previous post](https://dev.to/fraggedreality/implementing-a-proxy-contract-for-the-game-engine-to-log-solution-steps-in-fca00c-24pl) we discussed how to implement a proxy contract for the `game_engine` to log solution-steps in [fca00c:Asteroids](https://fastcheapandoutofcontrol.com/game/asteroids/play). Now let's add a bit of flesh to it.

## Recap
We have learned that in [soroban](https://soroban.stellar.org)
 - 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](https://github.com/hanseartic/fca00c-asteroids/tree/logging_engine)

## Adding actual logging to the existing `logging_engine`
Let's continue where we left off: https://github.com/hanseartic/fca00c-asteroids/tree/proxy_engine.
[![Open in GitHub Codespaces](https://github.com/codespaces/badge.svg)](https://github.com/codespaces/new?hide_repo_select=true&ref=logging_engine&repo=620754220&machine=basicLinux32gb&location=WestEurope)

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:
```rust
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: 
```diff
     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](https://github.com/hanseartic/fca00c-asteroids/commit/8a11ed8)).

## Printing the recorded actions in test
To see the recorded actions we need to print them in the test-case.
```diff
--- 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
```bash
❯ 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.
```diff
--- 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:
```diff
--- 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:
```bash
🗒️ 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](https://github.com/hanseartic/fca00c-asteroids/commit/c52d27a).

## 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.

```diff
--- 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
```diff
--- 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:

```diff
--- 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:
```bash
🗒️ 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](https://fastcheapandoutofcontrol.com/game/asteroids/play) 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.