Unverified Commit 2458e0c0 authored by Andrew Jones's avatar Andrew Jones Committed by GitHub
Browse files

Implement `seal_debug_message` (#792)



* Implement `seal_debug_message`

* Update docs

* Fmt

* Fix debug_print macro

* review: use newline char
Co-authored-by: default avatarRobin Freyler <robin.freyler@gmail.com>

* Fix example

* Revert to newline string

* Fmt

* Single call to debug_print for debug_println!

* Add missing ReturnCode, still need to handle it

* Inline debug_println!

* If logging is disabled then subsequent calls will be a no-op

* Fmt

* Fix missing error match in experimental off-chain

* Add safety comment to debug_message

* Only re-export ink_prelude::format, and explain

* Satisfy clippy

* Encapsulate DEBUG_ENABLED global in module

* Move seal_denug_message to unstable module

* Update unstable and safety comments

* Add more comments about the required features to be enabled on the node runtime

* Add `ink-debug` feature, make debug messages a noop if not enabled

* Fmt

* Noop macro formatting

* Enable debug printing for std

* Comment formatting

* Encapsulate static variable inside the function

* Fmt

* Remove debug_assert!(true) for disabled macros
Co-authored-by: default avatarRobin Freyler <robin.freyler@gmail.com>
parent d4fd3f78
Pipeline #141392 passed with stages
in 28 minutes and 48 seconds
......@@ -91,6 +91,9 @@ define_error_codes! {
CodeNotFound = 7,
/// The account that was called is either no contract (e.g. user account) or is a tombstone.
NotCallable = 8,
/// The call to `seal_debug_message` had no effect because debug message
/// recording was disabled.
LoggingDisabled = 9,
}
/// The raw return code returned by the host side.
......@@ -317,10 +320,10 @@ impl Engine {
unimplemented!("off-chain environment does not yet support `restore_to`");
}
/// Prints the given contents to the console log.
pub fn println(&mut self, content: &str) {
self.debug_info.record_println(String::from(content));
println!("{}", content);
/// Records the given debug message and appends to stdout.
pub fn debug_message(&mut self, message: &str) {
self.debug_info.record_debug_message(String::from(message));
print!("{}", message);
}
/// Conduct the BLAKE-2 256-bit hash and place the result into `output`.
......
......@@ -33,41 +33,41 @@ pub struct EmittedEvent {
}
#[derive(Clone)]
pub struct RecordedPrintlns {
printlns: Vec<String>,
pub struct RecordedDebugMessages {
debug_messages: Vec<String>,
}
impl RecordedPrintlns {
impl RecordedDebugMessages {
// Creates a new `Engine instance.
pub fn new() -> Self {
Self {
printlns: Vec::new(),
debug_messages: Vec::new(),
}
}
// Records a new println.
pub fn record(&mut self, println: String) {
self.printlns.push(println);
// Records a new debug message.
pub fn record(&mut self, message: String) {
self.debug_messages.push(message);
}
// Clears all recorded printlns.
// Clears all recorded debug messages.
pub fn clear(&mut self) {
self.printlns.clear();
self.debug_messages.clear();
}
}
impl Default for RecordedPrintlns {
impl Default for RecordedDebugMessages {
fn default() -> Self {
Self::new()
}
}
impl IntoIterator for RecordedPrintlns {
impl IntoIterator for RecordedDebugMessages {
type Item = String;
type IntoIter = std::vec::IntoIter<Self::Item>;
fn into_iter(self) -> Self::IntoIter {
self.printlns.into_iter()
self.debug_messages.into_iter()
}
}
......@@ -76,7 +76,7 @@ pub struct DebugInfo {
/// Emitted events recorder.
emitted_events: Vec<EmittedEvent>,
/// Emitted print messages recorder.
emitted_printlns: RecordedPrintlns,
emitted_debug_messages: RecordedDebugMessages,
/// The total number of reads to the storage.
count_reads: HashMap<AccountId, usize>,
/// The total number of writes to the storage.
......@@ -96,7 +96,7 @@ impl DebugInfo {
pub fn new() -> Self {
Self {
emitted_events: Vec::new(),
emitted_printlns: RecordedPrintlns::new(),
emitted_debug_messages: RecordedDebugMessages::new(),
count_reads: HashMap::new(),
count_writes: HashMap::new(),
cells_per_account: HashMap::new(),
......@@ -108,7 +108,7 @@ impl DebugInfo {
self.count_reads.clear();
self.count_writes.clear();
self.emitted_events.clear();
self.emitted_printlns.clear();
self.emitted_debug_messages.clear();
self.cells_per_account.clear();
}
......@@ -159,9 +159,9 @@ impl DebugInfo {
.unwrap_or(None)
}
/// Records a println.
pub fn record_println(&mut self, println: String) {
self.emitted_printlns.record(println);
/// Records a debug message.
pub fn record_debug_message(&mut self, message: String) {
self.emitted_debug_messages.record(message);
}
/// Records an event.
......@@ -215,9 +215,9 @@ impl Engine {
self.exec_context.callee()
}
/// Returns the contents of the past performed environmental `println` in order.
pub fn get_recorded_printlns(&self) -> RecordedPrintlns {
self.debug_info.emitted_printlns.clone()
/// Returns the contents of the past performed environmental `debug_message` in order.
pub fn get_emitted_debug_messages(&self) -> RecordedDebugMessages {
self.debug_info.emitted_debug_messages.clone()
}
/// Returns the recorded emitted events in order.
......
......@@ -115,10 +115,10 @@ fn transfer() {
}
#[test]
fn printlns() {
fn debug_messages() {
let mut engine = Engine::new();
engine.println("foobar");
let mut recorded = engine.get_recorded_printlns().into_iter();
engine.debug_message("foobar");
let mut recorded = engine.get_emitted_debug_messages().into_iter();
assert_eq!(recorded.next(), Some("foobar".into()));
assert_eq!(recorded.next(), None);
}
......
......@@ -62,4 +62,6 @@ std = [
"sha3",
"blake2",
]
# Enable contract debug messages via `debug_print!` and `debug_println!`.
ink-debug = []
ink-experimental-engine = ["ink_engine"]
......@@ -553,10 +553,10 @@ where
})
}
/// Prints the given contents to the environmental log.
pub fn debug_println(content: &str) {
/// Appends the given message to the debug message buffer.
pub fn debug_message(message: &str) {
<EnvInstance as OnInstance>::on_instance(|instance| {
EnvBackend::println(instance, content)
EnvBackend::debug_message(instance, message)
})
}
......
......@@ -119,8 +119,15 @@ pub trait EnvBackend {
where
R: scale::Encode;
/// Prints the given contents to the console log.
fn println(&mut self, content: &str);
/// Emit a custom debug message.
///
/// The message is appended to the debug buffer which is then supplied to the calling RPC
/// client. This buffer is also printed as a debug message to the node console if the
/// `debug` log level is enabled for the `runtime::contracts` target.
///
/// If debug message recording is disabled in the contracts pallet, which is always the case
/// when the code is executing on-chain, then this will have no effect.
fn debug_message(&mut self, content: &str);
/// Conducts the crypto hash of the given input and stores the result in `output`.
fn hash_bytes<H>(&mut self, input: &[u8], output: &mut <H as HashOutput>::Type)
......
......@@ -111,6 +111,7 @@ impl From<ext::Error> for crate::Error {
ext::Error::NewContractNotFunded => Self::NewContractNotFunded,
ext::Error::CodeNotFound => Self::CodeNotFound,
ext::Error::NotCallable => Self::NotCallable,
ext::Error::LoggingDisabled => Self::LoggingDisabled,
}
}
}
......@@ -227,8 +228,8 @@ impl EnvBackend for EnvInstance {
)
}
fn println(&mut self, content: &str) {
self.engine.println(content)
fn debug_message(&mut self, message: &str) {
self.engine.debug_message(message)
}
fn hash_bytes<H>(&mut self, input: &[u8], output: &mut <H as HashOutput>::Type)
......
......@@ -23,7 +23,7 @@ use crate::{
Result,
};
use core::fmt::Debug;
use ink_engine::test_api::RecordedPrintlns;
use ink_engine::test_api::RecordedDebugMessages;
use std::panic::UnwindSafe;
/// Record for an emitted event.
......@@ -129,10 +129,10 @@ where
unimplemented!("off-chain environment does not yet support `set_block_entropy`");
}
/// Returns the contents of the past performed environmental `println` in order.
pub fn recorded_printlns() -> RecordedPrintlns {
/// Returns the contents of the past performed environmental debug messages in order.
pub fn recorded_debug_messages() -> RecordedDebugMessages {
<EnvInstance as OnInstance>::on_instance(|instance| {
instance.engine.get_recorded_printlns()
instance.engine.get_emitted_debug_messages()
})
}
......
......@@ -14,53 +14,53 @@
use ink_prelude::string::String;
/// A debug console used to print console contents and store them.
pub struct Console {
/// The buffer to store the already pasted contents.
past_prints: Vec<String>,
/// A debug buffer used to store debug messages and print them to stdout.
pub struct DebugBuffer {
/// The buffer to store the emitted debug messages.
past_debug_messages: Vec<String>,
}
impl Console {
impl DebugBuffer {
/// Creates a new empty console.
pub fn new() -> Self {
Self {
past_prints: Vec::new(),
past_debug_messages: Vec::new(),
}
}
/// Resets the console to uninitialized state.
/// Resets the debug buffer to uninitialized state.
pub fn reset(&mut self) {
self.past_prints.clear();
self.past_debug_messages.clear();
}
/// Prints the contents to the actual console and stores them.
pub fn println(&mut self, contents: &str) {
self.past_prints.push(contents.to_string());
println!("{}", contents);
/// Prints the message to stdout and stores it.
pub fn debug_message(&mut self, message: &str) {
self.past_debug_messages.push(message.to_string());
print!("{}", message);
}
/// Returns an iterator over the past console prints.
pub fn past_prints(&self) -> PastPrints {
PastPrints::new(self)
/// Returns an iterator over the past debug messages.
pub fn past_debug_messages(&self) -> DebugMessages {
DebugMessages::new(self)
}
}
/// Iterator over the past prints to the console.
pub struct PastPrints<'a> {
/// Iterator over the past printlns.
/// Iterator over the past debug messages.
pub struct DebugMessages<'a> {
/// Iterator over the past debug messages.
iter: core::slice::Iter<'a, String>,
}
impl<'a> PastPrints<'a> {
/// Creates a new iterator over the past console prints.
fn new(console: &'a Console) -> Self {
impl<'a> DebugMessages<'a> {
/// Creates a new iterator over the past debug messages.
fn new(console: &'a DebugBuffer) -> Self {
Self {
iter: console.past_prints.iter(),
iter: console.past_debug_messages.iter(),
}
}
}
impl<'a> Iterator for PastPrints<'a> {
impl<'a> Iterator for DebugMessages<'a> {
type Item = &'a str;
fn next(&mut self) -> Option<Self::Item> {
......@@ -68,13 +68,13 @@ impl<'a> Iterator for PastPrints<'a> {
}
}
impl<'a> ExactSizeIterator for PastPrints<'a> {
impl<'a> ExactSizeIterator for DebugMessages<'a> {
fn len(&self) -> usize {
self.iter.len()
}
}
impl<'a> DoubleEndedIterator for PastPrints<'a> {
impl<'a> DoubleEndedIterator for DebugMessages<'a> {
fn next_back(&mut self) -> Option<Self::Item> {
self.iter.next_back().map(AsRef::as_ref)
}
......
......@@ -15,7 +15,7 @@
mod accounts;
mod block;
mod chain_spec;
mod console;
mod debug_buf;
mod events;
mod exec_context;
......@@ -30,9 +30,9 @@ pub use self::{
},
block::Block,
chain_spec::ChainSpec,
console::{
Console,
PastPrints,
debug_buf::{
DebugBuffer,
DebugMessages,
},
events::{
EmittedEvent,
......
......@@ -175,8 +175,8 @@ impl EnvBackend for EnvInstance {
std::process::exit(flags.into_u32() as i32)
}
fn println(&mut self, content: &str) {
self.console.println(content)
fn debug_message(&mut self, message: &str) {
self.debug_buf.debug_message(message)
}
fn hash_bytes<H>(&mut self, input: &[u8], output: &mut <H as HashOutput>::Type)
......
......@@ -28,8 +28,8 @@ pub use self::{
call_data::CallData,
db::{
AccountError,
DebugMessages,
EmittedEvent,
PastPrints,
},
typed_encoded::TypedEncodedError,
};
......@@ -40,7 +40,7 @@ use self::{
AccountsDb,
Block,
ChainSpec,
Console,
DebugBuffer,
EmittedEventsRecorder,
ExecContext,
},
......@@ -84,8 +84,8 @@ pub struct EnvInstance {
chain_spec: ChainSpec,
/// The blocks of the chain.
blocks: Vec<Block>,
/// The console to print debug contents.
console: Console,
/// The debug buffer to collect debug messages and print them to stdout.
debug_buf: DebugBuffer,
/// Handler for registered chain extensions.
chain_extension_handler: ChainExtensionHandler,
/// Emitted events recorder.
......@@ -102,7 +102,7 @@ impl EnvInstance {
exec_context: Vec::new(),
chain_spec: ChainSpec::uninitialized(),
blocks: Vec::new(),
console: Console::new(),
debug_buf: DebugBuffer::new(),
chain_extension_handler: ChainExtensionHandler::new(),
emitted_events: EmittedEventsRecorder::new(),
clear_storage_disabled: false,
......@@ -133,7 +133,7 @@ impl EnvInstance {
self.exec_context.clear();
self.chain_spec.reset();
self.blocks.clear();
self.console.reset();
self.debug_buf.reset();
self.chain_extension_handler.reset();
self.emitted_events.reset();
self.clear_storage_disabled = false;
......
......@@ -215,8 +215,8 @@ where
Ok(())
}
/// Returns the contents of the past performed environmental `println` in order.
pub fn recorded_printlns() -> impl Iterator<Item = String> {
/// Returns the contents of the past performed environmental debug messages in order.
pub fn recorded_debug_messages() -> impl Iterator<Item = String> {
<EnvInstance as OnInstance>::on_instance(|instance| {
// We return a clone of the recorded strings instead of
// references to them since this would require the whole `on_instance`
......@@ -224,8 +224,8 @@ pub fn recorded_printlns() -> impl Iterator<Item = String> {
// ultimately allow leaking those `'static` references to the outside
// and potentially lead to terrible bugs such as iterator invalidation.
instance
.console
.past_prints()
.debug_buf
.past_debug_messages()
.map(ToOwned::to_owned)
.collect::<Vec<_>>()
.into_iter()
......
......@@ -76,6 +76,9 @@ define_error_codes! {
CodeNotFound = 7,
/// The account that was called is either no contract (e.g. user account) or is a tombstone.
NotCallable = 8,
/// The call to `seal_debug_message` had no effect because debug message
/// recording was disabled.
LoggingDisabled = 9,
}
/// Thin-wrapper around a `u32` representing a pointer for Wasm32.
......@@ -308,8 +311,6 @@ mod sys {
pub fn seal_set_rent_allowance(value_ptr: Ptr32<[u8]>, value_len: u32);
pub fn seal_println(str_ptr: Ptr32<[u8]>, str_len: u32);
pub fn seal_hash_keccak_256(
input_ptr: Ptr32<[u8]>,
input_len: u32,
......@@ -344,6 +345,9 @@ mod sys {
#[link(wasm_import_module = "__unstable__")]
extern "C" {
#[cfg(feature = "ink-debug")]
pub fn seal_debug_message(str_ptr: Ptr32<[u8]>, str_len: u32) -> ReturnCode;
pub fn seal_rent_params(
output_ptr: Ptr32Mut<[u8]>,
output_len_ptr: Ptr32Mut<u32>,
......@@ -645,11 +649,37 @@ pub fn random(subject: &[u8], output: &mut &mut [u8]) {
extract_from_slice(output, output_len as usize);
}
pub fn println(content: &str) {
let bytes = content.as_bytes();
unsafe { sys::seal_println(Ptr32::from_slice(bytes), bytes.len() as u32) }
#[cfg(feature = "ink-debug")]
/// Call `seal_debug_message` with the supplied UTF-8 encoded message.
///
/// If debug message recording is disabled in the contracts pallet, the first call to will
/// return LoggingDisabled error, and further calls will be a no-op to avoid the cost of calling
/// into the supervisor.
///
/// # Note
///
/// This depends on the the `seal_debug_message` interface which requires the
/// `"pallet-contracts/unstable-interface"` feature to be enabled in the target runtime.
pub fn debug_message(message: &str) {
static mut DEBUG_ENABLED: bool = true;
// SAFETY: safe because executing in a single threaded context
if unsafe { DEBUG_ENABLED } {
let bytes = message.as_bytes();
let ret_code = unsafe {
sys::seal_debug_message(Ptr32::from_slice(bytes), bytes.len() as u32)
};
if let Err(Error::LoggingDisabled) = ret_code.into() {
// SAFETY: safe because executing in a single threaded context
unsafe { DEBUG_ENABLED = false }
}
}
}
#[cfg(not(feature = "ink-debug"))]
/// A no-op. Enable the `ink-debug` feature for debug messages.
pub fn debug_message(_message: &str) {}
macro_rules! impl_hash_fn {
( $name:ident, $bytes_result:literal ) => {
paste::item! {
......
......@@ -110,6 +110,7 @@ impl From<ext::Error> for Error {
ext::Error::NewContractNotFunded => Self::NewContractNotFunded,
ext::Error::CodeNotFound => Self::CodeNotFound,
ext::Error::NotCallable => Self::NotCallable,
ext::Error::LoggingDisabled => Self::LoggingDisabled,
}
}
}
......@@ -255,8 +256,8 @@ impl EnvBackend for EnvInstance {
ext::return_value(flags, enc_return_value);
}
fn println(&mut self, content: &str) {
ext::println(content)
fn debug_message(&mut self, content: &str) {
ext::debug_message(content)
}
fn hash_bytes<H>(&mut self, input: &[u8], output: &mut <H as HashOutput>::Type)
......
......@@ -46,6 +46,9 @@ pub enum Error {
NotCallable,
/// An unknown error has occurred.
UnknownError,
/// The call to `seal_debug_message` had no effect because debug message
/// recording was disabled.
LoggingDisabled,
}
/// A result of environmental operations.
......
......@@ -102,3 +102,55 @@ pub use self::{
RentStatus,
},
};
cfg_if::cfg_if! {
if #[cfg(any(feature = "ink-debug", feature = "std"))] {
/// Required by the `debug_print*` macros below, because there is no guarantee that
/// contracts will have a direct `ink_prelude` dependency. In the future we could introduce
/// an "umbrella" crate containing all the `ink!` crates which could also host these macros.
#[doc(hidden)]
pub use ink_prelude::format;
/// Appends a formatted string to the `debug_message` buffer which will be:
/// - Returned to the caller when the contract is invoked via RPC (*not* via an extrinsic)
/// - Logged as a `debug!` message on the substrate node, which will be printed to the node
/// console's `stdout` when the log level is set to `debug`.
///
/// # Note
///
/// This depends on the the `seal_debug_message` interface which requires the
/// `"pallet-contracts/unstable-interface"` feature to be enabled in the target runtime.
#[macro_export]
macro_rules! debug_print {
($($arg:tt)*) => ($crate::debug_message(&$crate::format!($($arg)*)));
}
/// Appends a formatted string to the `debug_message` buffer, as per [`debug_print`] but
/// with a newline appended.
///
/// # Note
///
/// This depends on the the `seal_debug_message` interface which requires the
/// `"pallet-contracts/unstable-interface"` feature to be enabled in the target runtime.
#[macro_export]
macro_rules! debug_println {
() => ($crate::debug_print!("\n"));
($($arg:tt)*) => (
$crate::debug_print!("{}\n", $crate::format!($($arg)*));
)
}
} else {
#[macro_export]
/// Debug messages disabled. Enable the `ink-debug` feature for contract debugging.
macro_rules! debug_print {
($($arg:tt)*) => ();
}
#[macro_export]
/// Debug messages disabled. Enable the `ink-debug` feature for contract debugging.
macro_rules! debug_println {
() => ();
($($arg:tt)*) => ();
}
}
}
......@@ -399,7 +399,7 @@ use proc_macro::TokenStream;
/// #
/// #[ink::contract]
/// mod greeter {
/// use ink_prelude::format;
/// use ink_env::debug_println;
///
/// #[ink(storage)]
/// pub struct Greeter;
......@@ -408,8 +408,7 @@ use proc_macro::TokenStream;
/// #[ink(constructor)]
/// pub fn new() -> Self {
/// let caller = Self::env().caller();
/// let message = format!("thanks for instantiation {:?}", caller);
/// ink_env::debug_println(&message);
/// debug_println!("thanks for instantiation {:?}", caller);
/// Greeter {}
/// }
///
......@@ -417,8 +416,7 @@ use proc_macro::TokenStream;
/// pub fn fund(&self) {
/// let caller = self.env().caller();