From 25b5de9f7b5dd53eb2321821a2cd5e42d2662580 Mon Sep 17 00:00:00 2001 From: anishnaik Date: Fri, 14 Jul 2023 12:06:41 -0400 Subject: [PATCH] Custom logger for unstructured and structured logging (#171) This PR introduces colorized logging for console and future support for structured logging --------- Co-authored-by: David Pokora --- chain/cheat_code_contract.go | 6 +- cmd/completion.go | 35 +- cmd/fuzz.go | 89 +++-- cmd/init.go | 96 +++-- cmd/root.go | 6 + compilation/supported_platforms.go | 4 +- fuzzing/calls/call_message.go | 4 +- fuzzing/calls/call_sequence.go | 39 +- fuzzing/config/config.go | 40 +- fuzzing/config/config_defaults.go | 5 + fuzzing/corpus/corpus.go | 8 +- fuzzing/coverage/coverage_tracer.go | 12 +- fuzzing/executiontracer/execution_trace.go | 134 ++++--- fuzzing/fuzzer.go | 102 +++-- fuzzing/fuzzer_test.go | 6 +- fuzzing/test_case.go | 7 +- fuzzing/test_case_assertion.go | 29 +- fuzzing/test_case_optimization.go | 42 ++- fuzzing/test_case_optimization_provider.go | 5 - fuzzing/test_case_property.go | 35 +- fuzzing/valuegeneration/abi_values.go | 6 +- go.mod | 3 + go.sum | 11 + logging/colors/color_funcs.go | 107 ++++++ logging/colors/colorize_unix.go | 15 + logging/colors/colorize_windows.go | 66 ++++ logging/colors/constants.go | 34 ++ logging/colors/init.go | 7 + logging/log_buffer.go | 33 ++ logging/logger.go | 347 ++++++++++++++++++ main.go | 4 - utils/fs_utils.go | 27 ++ utils/randomutils/fork_random.go | 3 +- utils/reflectionutils/reflected_type_utils.go | 13 +- 34 files changed, 1122 insertions(+), 258 deletions(-) create mode 100644 logging/colors/color_funcs.go create mode 100644 logging/colors/colorize_unix.go create mode 100644 logging/colors/colorize_windows.go create mode 100644 logging/colors/constants.go create mode 100644 logging/colors/init.go create mode 100644 logging/log_buffer.go create mode 100644 logging/logger.go diff --git a/chain/cheat_code_contract.go b/chain/cheat_code_contract.go index 43b8fa2f..0b644cfc 100644 --- a/chain/cheat_code_contract.go +++ b/chain/cheat_code_contract.go @@ -2,6 +2,8 @@ package chain import ( "encoding/binary" + "fmt" + "github.com/crytic/medusa/logging" "github.com/ethereum/go-ethereum/accounts/abi" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/core/vm" @@ -100,12 +102,12 @@ func (c *CheatCodeContract) Abi() *abi.ABI { func (c *CheatCodeContract) addMethod(name string, inputs abi.Arguments, outputs abi.Arguments, handler cheatCodeMethodHandler) { // Verify a method name was provided if name == "" { - panic("could not add method to precompiled cheatcode contract, empty method name provided") + logging.GlobalLogger.Panic("Failed to add method to precompile cheatcode contract", fmt.Errorf("empty method name provided")) } // Verify a method handler was provided if handler == nil { - panic("could not add method to precompiled cheatcode contract, nil method handler provided") + logging.GlobalLogger.Panic("Failed to add method to precompile cheatcode contract", fmt.Errorf("nil method handler provided")) } // Set the method information in our method lookup diff --git a/cmd/completion.go b/cmd/completion.go index 57e45539..a5e1f66a 100644 --- a/cmd/completion.go +++ b/cmd/completion.go @@ -47,11 +47,13 @@ var supportedShells = []string{"bash", "zsh", "powershell"} // completionCmd represents the completion command var completionCmd = &cobra.Command{ - Use: "completion ", - Short: "generate the autocompletion script for medusa for the specific shell", - Long: generalComDesc, - Args: cmdValidateCompletionArgs, - RunE: cmdRunCompletion, + Use: "completion ", + Short: "Generate the autocompletion script for medusa for the specific shell", + Long: generalComDesc, + Args: cmdValidateCompletionArgs, + RunE: cmdRunCompletion, + SilenceUsage: true, + SilenceErrors: true, } func init() { @@ -62,12 +64,16 @@ func init() { func cmdValidateCompletionArgs(cmd *cobra.Command, args []string) error { // Make sure we have exactly 1 argument if err := cobra.ExactArgs(1)(cmd, args); err != nil { - return fmt.Errorf("completion requires only 1 shell argument (options: %s)", strings.Join(supportedShells, ", ")) + err = fmt.Errorf("completion requires only 1 shell argument (options: %s)", strings.Join(supportedShells, ", ")) + cmdLogger.Error("Failed to validate args for completion command", err) + return err } // Make sure that the shell is a supported type if contains := slices.Contains(supportedShells, args[0]); !contains { - return fmt.Errorf("%s is not a supported shell", args[0]) + err := fmt.Errorf("%s is not a supported shell", args[0]) + cmdLogger.Error("Failed to validate args for completion command", err) + return err } return nil @@ -76,15 +82,22 @@ func cmdValidateCompletionArgs(cmd *cobra.Command, args []string) error { // cmdRunCompletion executes the completion CLI command func cmdRunCompletion(cmd *cobra.Command, args []string) error { // NOTE: Please be aware that if the supported shells changes, then this switch statement must also change + var err error switch args[0] { case "bash": - return cmd.Root().GenBashCompletionV2(os.Stdout, true) + err = cmd.Root().GenBashCompletionV2(os.Stdout, true) case "zsh": - return cmd.Root().GenZshCompletion(os.Stdout) + err = cmd.Root().GenZshCompletion(os.Stdout) case "powershell": - return cmd.Root().GenPowerShellCompletionWithDesc(os.Stdout) + err = cmd.Root().GenPowerShellCompletionWithDesc(os.Stdout) default: // We are throwing a panic here because our validation function should have handled this and something is wrong. - panic(fmt.Errorf("%s is not a supported shell type", args[0])) + cmdLogger.Panic("Failed to run the completion command", fmt.Errorf("%s is not a supported shell type", args[0])) } + + // Log an error if we encountered one + if err != nil { + cmdLogger.Error("Failed to run the completion command", err) + } + return err } diff --git a/cmd/fuzz.go b/cmd/fuzz.go index c77ac5e0..3fc22fd3 100644 --- a/cmd/fuzz.go +++ b/cmd/fuzz.go @@ -2,6 +2,7 @@ package cmd import ( "fmt" + "github.com/crytic/medusa/logging/colors" "os" "os/signal" "path/filepath" @@ -14,53 +15,59 @@ import ( // fuzzCmd represents the command provider for fuzzing var fuzzCmd = &cobra.Command{ - Use: "fuzz", - Short: "Starts a fuzzing campaign", - Long: `Starts a fuzzing campaign`, - Args: cmdValidateFuzzArgs, - RunE: cmdRunFuzz, - // Run dynamic completion of nouns - ValidArgsFunction: func(cmd *cobra.Command, args []string, toComplete string) ([]string, cobra.ShellCompDirective) { - // Gather a list of flags that are available to be used in the current command but have not been used yet - var unusedFlags []string - - // Examine all the flags, and add any flags that have not been set in the current command line - // to a list of unused flags - cmd.Flags().VisitAll(func(flag *pflag.Flag) { - if !flag.Changed { - // When adding a flag to a command, include the "--" prefix to indicate that it is a flag - // and not a positional argument. Additionally, when the user presses the TAB key twice after typing - // a flag name, the "--" prefix will appear again, indicating that more flags are available and that - // none of the arguments are positional. - unusedFlags = append(unusedFlags, "--"+flag.Name) - } - }) - // Provide a list of flags that can be used in the current command (but have not been used yet) - // for autocompletion suggestions - return unusedFlags, cobra.ShellCompDirectiveNoFileComp - }, -} - -// cmdValidateFuzzArgs makes sure that there are no positional arguments provided to the fuzz command -func cmdValidateFuzzArgs(cmd *cobra.Command, args []string) error { - // Make sure we have no positional args - if err := cobra.NoArgs(cmd, args); err != nil { - return fmt.Errorf("fuzz does not accept any positional arguments, only flags and their associated values") - } - return nil + Use: "fuzz", + Short: "Starts a fuzzing campaign", + Long: `Starts a fuzzing campaign`, + Args: cmdValidateFuzzArgs, + ValidArgsFunction: cmdValidFuzzArgs, + RunE: cmdRunFuzz, + SilenceUsage: true, + SilenceErrors: true, } func init() { // Add all the flags allowed for the fuzz command err := addFuzzFlags() if err != nil { - panic(err) + cmdLogger.Panic("Failed to initialize the fuzz command", err) } // Add the fuzz command and its associated flags to the root command rootCmd.AddCommand(fuzzCmd) } +// cmdValidFuzzArgs will return which flags and sub-commands are valid for dynamic completion for the fuzz command +func cmdValidFuzzArgs(cmd *cobra.Command, args []string, toComplete string) ([]string, cobra.ShellCompDirective) { + // Gather a list of flags that are available to be used in the current command but have not been used yet + var unusedFlags []string + + // Examine all the flags, and add any flags that have not been set in the current command line + // to a list of unused flags + cmd.Flags().VisitAll(func(flag *pflag.Flag) { + if !flag.Changed { + // When adding a flag to a command, include the "--" prefix to indicate that it is a flag + // and not a positional argument. Additionally, when the user presses the TAB key twice after typing + // a flag name, the "--" prefix will appear again, indicating that more flags are available and that + // none of the arguments are positional. + unusedFlags = append(unusedFlags, "--"+flag.Name) + } + }) + // Provide a list of flags that can be used in the current command (but have not been used yet) + // for autocompletion suggestions + return unusedFlags, cobra.ShellCompDirectiveNoFileComp +} + +// cmdValidateFuzzArgs makes sure that there are no positional arguments provided to the fuzz command +func cmdValidateFuzzArgs(cmd *cobra.Command, args []string) error { + // Make sure we have no positional args + if err := cobra.NoArgs(cmd, args); err != nil { + err = fmt.Errorf("fuzz does not accept any positional arguments, only flags and their associated values") + cmdLogger.Error("Failed to validate args to the fuzz command", err) + return err + } + return nil +} + // cmdRunFuzz executes the CLI fuzz command and navigates through the following possibilities: // #1: We will search for either a custom config file (via --config) or the default (medusa.json). // If we find it, read it. If we can't read it, throw an error. @@ -73,6 +80,7 @@ func cmdRunFuzz(cmd *cobra.Command, args []string) error { configFlagUsed := cmd.Flags().Changed("config") configPath, err := cmd.Flags().GetString("config") if err != nil { + cmdLogger.Error("Failed to run the fuzz command", err) return err } @@ -80,6 +88,7 @@ func cmdRunFuzz(cmd *cobra.Command, args []string) error { if !configFlagUsed { workingDirectory, err := os.Getwd() if err != nil { + cmdLogger.Error("Failed to run the fuzz command", err) return err } configPath = filepath.Join(workingDirectory, DefaultProjectConfigFilename) @@ -91,24 +100,28 @@ func cmdRunFuzz(cmd *cobra.Command, args []string) error { // Possibility #1: File was found if existenceError == nil { // Try to read the configuration file and throw an error if something goes wrong + cmdLogger.Info("Reading the configuration file at: ", colors.Bold, configPath, colors.Reset) projectConfig, err = config.ReadProjectConfigFromFile(configPath) if err != nil { + cmdLogger.Error("Failed to run the fuzz command", err) return err } } // Possibility #2: If the --config flag was used, and we couldn't find the file, we'll throw an error if configFlagUsed && existenceError != nil { + cmdLogger.Error("Failed to run the fuzz command", err) return existenceError } // Possibility #3: --config flag was not used and medusa.json was not found, so use the default project config if !configFlagUsed && existenceError != nil { - fmt.Printf("unable to find the config file at %v. will use the default project configuration for the "+ - "%v compilation platform instead\n", configPath, DefaultCompilationPlatform) + cmdLogger.Warn(fmt.Sprintf("Unable to find the config file at %v, will use the default project configuration for the "+ + "%v compilation platform instead", configPath, DefaultCompilationPlatform)) projectConfig, err = config.GetDefaultProjectConfig(DefaultCompilationPlatform) if err != nil { + cmdLogger.Error("Failed to run the fuzz command", err) return err } } @@ -116,6 +129,7 @@ func cmdRunFuzz(cmd *cobra.Command, args []string) error { // Update the project configuration given whatever flags were set using the CLI err = updateProjectConfigWithFuzzFlags(cmd, projectConfig) if err != nil { + cmdLogger.Error("Failed to run the fuzz command", err) return err } @@ -125,6 +139,7 @@ func cmdRunFuzz(cmd *cobra.Command, args []string) error { // be in the config directory when running this. err = os.Chdir(filepath.Dir(configPath)) if err != nil { + cmdLogger.Error("Failed to run the fuzz command", err) return err } diff --git a/cmd/init.go b/cmd/init.go index 79087667..4f845517 100644 --- a/cmd/init.go +++ b/cmd/init.go @@ -2,6 +2,7 @@ package cmd import ( "fmt" + "github.com/crytic/medusa/logging/colors" "os" "path/filepath" "strings" @@ -18,66 +19,74 @@ var supportedPlatforms = compilation.GetSupportedCompilationPlatforms() // initCmd represents the command provider for init var initCmd = &cobra.Command{ - Use: "init [platform]", - Short: "Initializes a project configuration", - Long: `Initializes a project configuration`, - Args: cmdValidateInitArgs, - RunE: cmdRunInit, - // Run dynamic completion of nouns - ValidArgsFunction: func(cmd *cobra.Command, args []string, toComplete string) ([]string, cobra.ShellCompDirective) { - // Gather a list of flags that are available to be used in the current command but have not been used yet - var unusedFlags []string - - // Examine all the flags, and add any flags that have not been set in the current command line - // to a list of unused flags - flagUsed := false - cmd.Flags().VisitAll(func(flag *pflag.Flag) { - if !flag.Changed { - // When adding a flag to a command, include the "--" prefix to indicate that it is a flag - // and not a positional argument. Additionally, when the user presses the TAB key twice after typing - // a flag name, the "--" prefix will appear again, indicating that more flags are available and that - // none of the arguments are positional. - unusedFlags = append(unusedFlags, "--"+flag.Name) - } else { - // If any flag has been used, set flag used to true. This will be used later in the function. - flagUsed = true - } - }) - - // If a default platform is not specified, add a list of available platforms to the list of unused flags. - // If any flag is used, then we can assume that the default platform is used so we don't need to add supported platforms - if len(args) == 0 && !flagUsed { - unusedFlags = append(unusedFlags, supportedPlatforms...) - } - - // Provide a list of flags that can be used in the current command (but have not been used yet) - // for autocompletion suggestions - return unusedFlags, cobra.ShellCompDirectiveNoFileComp - }, + Use: "init [platform]", + Short: "Initializes a project configuration", + Long: `Initializes a project configuration`, + Args: cmdValidateInitArgs, + ValidArgsFunction: cmdValidInitArgs, + RunE: cmdRunInit, + SilenceUsage: true, + SilenceErrors: true, } func init() { // Add flags to init command err := addInitFlags() if err != nil { - panic(err) + cmdLogger.Panic("Failed to initialize the init command", err) } // Add the init command and its associated flags to the root command rootCmd.AddCommand(initCmd) } +// cmdValidInitArgs will return which flags and sub-commands are valid for dynamic completion for the init command +func cmdValidInitArgs(cmd *cobra.Command, args []string, toComplete string) ([]string, cobra.ShellCompDirective) { + // Gather a list of flags that are available to be used in the current command but have not been used yet + var unusedFlags []string + + // Examine all the flags, and add any flags that have not been set in the current command line + // to a list of unused flags + flagUsed := false + cmd.Flags().VisitAll(func(flag *pflag.Flag) { + if !flag.Changed { + // When adding a flag to a command, include the "--" prefix to indicate that it is a flag + // and not a positional argument. Additionally, when the user presses the TAB key twice after typing + // a flag name, the "--" prefix will appear again, indicating that more flags are available and that + // none of the arguments are positional. + unusedFlags = append(unusedFlags, "--"+flag.Name) + } else { + // If any flag has been used, set flag used to true. This will be used later in the function. + flagUsed = true + } + }) + + // If a default platform is not specified, add a list of available platforms to the list of unused flags. + // If any flag is used, then we can assume that the default platform is used so we don't need to add supported platforms + if len(args) == 0 && !flagUsed { + unusedFlags = append(unusedFlags, supportedPlatforms...) + } + + // Provide a list of flags that can be used in the current command (but have not been used yet) + // for autocompletion suggestions + return unusedFlags, cobra.ShellCompDirectiveNoFileComp +} + // cmdValidateInitArgs validates CLI arguments func cmdValidateInitArgs(cmd *cobra.Command, args []string) error { // Make sure we have no more than 1 arg if err := cobra.RangeArgs(0, 1)(cmd, args); err != nil { - return fmt.Errorf("init accepts at most 1 platform argument (options: %s). "+ + err = fmt.Errorf("init accepts at most 1 platform argument (options: %s). "+ "default platform is %v\n", strings.Join(supportedPlatforms, ", "), DefaultCompilationPlatform) + cmdLogger.Error("Failed to validate args to the init command", err) + return err } // Ensure the optional provided argument refers to a supported platform if len(args) == 1 && !compilation.IsSupportedCompilationPlatform(args[0]) { - return fmt.Errorf("init was provided invalid platform argument '%s' (options: %s)", args[0], strings.Join(supportedPlatforms, ", ")) + err := fmt.Errorf("init was provided invalid platform argument '%s' (options: %s)", args[0], strings.Join(supportedPlatforms, ", ")) + cmdLogger.Error("Failed to validate args to the init command", err) + return err } return nil @@ -89,12 +98,14 @@ func cmdRunInit(cmd *cobra.Command, args []string) error { outputFlagUsed := cmd.Flags().Changed("out") outputPath, err := cmd.Flags().GetString("out") if err != nil { + cmdLogger.Error("Failed to run the init command", err) return err } // If we weren't provided an output path (flag was not used), we use our working directory if !outputFlagUsed { workingDirectory, err := os.Getwd() if err != nil { + cmdLogger.Error("Failed to run the init command", err) return err } outputPath = filepath.Join(workingDirectory, DefaultProjectConfigFilename) @@ -103,6 +114,7 @@ func cmdRunInit(cmd *cobra.Command, args []string) error { // By default, projectConfig will be the default project config for the DefaultCompilationPlatform projectConfig, err := config.GetDefaultProjectConfig(DefaultCompilationPlatform) if err != nil { + cmdLogger.Error("Failed to run the init command", err) return err } @@ -111,6 +123,8 @@ func cmdRunInit(cmd *cobra.Command, args []string) error { if len(args) == 1 && args[0] != DefaultCompilationPlatform { projectConfig, err = config.GetDefaultProjectConfig(args[0]) if err != nil { + cmdLogger.Error("Failed to run the init command", err) + return err } } @@ -118,12 +132,14 @@ func cmdRunInit(cmd *cobra.Command, args []string) error { // Update the project configuration given whatever flags were set using the CLI err = updateProjectConfigWithInitFlags(cmd, projectConfig) if err != nil { + cmdLogger.Error("Failed to run the init command", err) return err } // Write our project configuration err = projectConfig.WriteToFile(outputPath) if err != nil { + cmdLogger.Error("Failed to run the init command", err) return err } @@ -131,6 +147,6 @@ func cmdRunInit(cmd *cobra.Command, args []string) error { if absoluteOutputPath, err := filepath.Abs(outputPath); err == nil { outputPath = absoluteOutputPath } - fmt.Printf("Project configuration successfully output to: %s\n", outputPath) + cmdLogger.Info("Project configuration successfully output to: ", colors.Bold, outputPath, colors.Reset) return nil } diff --git a/cmd/root.go b/cmd/root.go index 4cd678f3..cfe2a15e 100644 --- a/cmd/root.go +++ b/cmd/root.go @@ -1,7 +1,10 @@ package cmd import ( + "github.com/crytic/medusa/logging" + "github.com/rs/zerolog" "github.com/spf13/cobra" + "io" ) const version = "0.1.0" @@ -14,6 +17,9 @@ var rootCmd = &cobra.Command{ Long: "medusa is a solidity smart contract fuzzing harness", } +// cmdLogger is the logger that will be used for the cmd package +var cmdLogger = logging.NewLogger(zerolog.InfoLevel, true, make([]io.Writer, 0)...) + // Execute provides an exportable function to invoke the CLI. // Returns an error if one was encountered. func Execute() error { diff --git a/compilation/supported_platforms.go b/compilation/supported_platforms.go index 91dd6732..55178abc 100644 --- a/compilation/supported_platforms.go +++ b/compilation/supported_platforms.go @@ -3,6 +3,7 @@ package compilation import ( "fmt" "github.com/crytic/medusa/compilation/platforms" + "github.com/crytic/medusa/logging" ) // defaultPlatformConfigGenerator is a mapping of platform identifier to generator functions which can be used to create @@ -30,7 +31,8 @@ func init() { // If this platform already exists in our mapping, panic. Each platform should have a unique identifier. if _, platformIdExists := defaultPlatformConfigGenerator[platformId]; platformIdExists { - panic(fmt.Errorf("the compilation platform '%s' is registered with more than one provider", platformId)) + err := fmt.Errorf("the compilation platform '%s' is registered with more than one provider", platformId) + logging.GlobalLogger.Panic("Failed to initialize default platform configurations", err) } // Add this entry to our mapping diff --git a/fuzzing/calls/call_message.go b/fuzzing/calls/call_message.go index 8bde25b0..de3a856f 100644 --- a/fuzzing/calls/call_message.go +++ b/fuzzing/calls/call_message.go @@ -1,8 +1,8 @@ package calls import ( - "fmt" "github.com/crytic/medusa/chain" + "github.com/crytic/medusa/logging" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/common/hexutil" coreTypes "github.com/ethereum/go-ethereum/core/types" @@ -138,7 +138,7 @@ func (m *CallMessage) Data() []byte { if m.MsgDataAbiValues != nil { data, err := m.MsgDataAbiValues.Pack() if err != nil { - panic(fmt.Errorf("error while packing call message ABI values: %v", err)) + logging.GlobalLogger.Panic("Failed to pack call message ABI values", err) } return data } diff --git a/fuzzing/calls/call_sequence.go b/fuzzing/calls/call_sequence.go index 872f3cca..41ae2ccc 100644 --- a/fuzzing/calls/call_sequence.go +++ b/fuzzing/calls/call_sequence.go @@ -4,17 +4,16 @@ import ( "encoding/binary" "fmt" "github.com/crytic/medusa/chain" + chainTypes "github.com/crytic/medusa/chain/types" + fuzzingTypes "github.com/crytic/medusa/fuzzing/contracts" "github.com/crytic/medusa/fuzzing/executiontracer" + "github.com/crytic/medusa/fuzzing/valuegeneration" + "github.com/crytic/medusa/logging" "github.com/crytic/medusa/utils" + "github.com/ethereum/go-ethereum/accounts/abi" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/crypto" "strconv" - "strings" - - chainTypes "github.com/crytic/medusa/chain/types" - fuzzingTypes "github.com/crytic/medusa/fuzzing/contracts" - "github.com/crytic/medusa/fuzzing/valuegeneration" - "github.com/ethereum/go-ethereum/accounts/abi" ) // CallSequence describes a sequence of calls sent to a chain. @@ -34,27 +33,37 @@ func (cs CallSequence) AttachExecutionTraces(chain *chain.TestChain, contractDef return nil } -// String returns a displayable string representing the CallSequence. -func (cs CallSequence) String() string { +// Log returns a logging.LogBuffer that represents this call sequence. This buffer will be passed to the underlying +// logger which will format it accordingly for console or file. +func (cs CallSequence) Log() *logging.LogBuffer { + buffer := logging.NewLogBuffer() // If we have an empty call sequence, return a special string if len(cs) == 0 { - return "" + buffer.Append("") + return buffer } - // Construct a list of strings for each call made in the sequence - var elementStrings []string + // Construct the buffer for each call made in the sequence for i := 0; i < len(cs); i++ { // Add the string representing the call - elementStrings = append(elementStrings, fmt.Sprintf("%d) %s", i+1, cs[i].String())) + buffer.Append(fmt.Sprintf("%d) %s\n", i+1, cs[i].String())) // If we have an execution trace attached, print information about it. if cs[i].ExecutionTrace != nil { - elementStrings = append(elementStrings, cs[i].ExecutionTrace.String()) + buffer.Append(cs[i].ExecutionTrace.Log().Elements()...) + buffer.Append("\n") } } - // Join each element with new lines and return it. - return strings.Join(elementStrings, "\n") + // Return the buffer + return buffer +} + +// String returns the string representation of this call sequence +func (cs CallSequence) String() string { + // Internally, we just call the log function, get the list of elements and create their non-colorized string representation + // Might be useful for 3rd party apps + return cs.Log().String() } // Clone creates a copy of the underlying CallSequence. diff --git a/fuzzing/config/config.go b/fuzzing/config/config.go index a0a60d3d..283e5329 100644 --- a/fuzzing/config/config.go +++ b/fuzzing/config/config.go @@ -3,8 +3,8 @@ package config import ( "encoding/json" "errors" - "fmt" "github.com/crytic/medusa/chain/config" + "github.com/rs/zerolog" "os" "github.com/crytic/medusa/compilation" @@ -17,6 +17,9 @@ type ProjectConfig struct { // Compilation describes the configuration used to compile the underlying project. Compilation *compilation.CompilationConfig `json:"compilation"` + + // Logging describes the configuration used for logging to file and console + Logging LoggingConfig `json:"logging"` } // FuzzingConfig describes the configuration options used by the fuzzing.Fuzzer. @@ -177,11 +180,38 @@ type OptimizationTestingConfig struct { TestPrefixes []string `json:"testPrefixes"` } +// LoggingConfig describes the configuration options for logging to console and file +type LoggingConfig struct { + // Level describes whether logs of certain severity levels (eg info, warning, etc.) will be emitted or discarded. + // Increasing level values represent more severe logs + Level zerolog.Level `json:"level"` + + // LogDirectory describes what directory log files should be outputted in/ LogDirectory being a non-empty string is + // equivalent to enabling file logging. + LogDirectory string `json:"logDirectory"` +} + +// ConsoleLoggingConfig describes the configuration options for logging to console. Note that this not being used right now +// but will be added to LoggingConfig down the line +// TODO: Update when implementing a structured logging solution +type ConsoleLoggingConfig struct { + // Enabled describes whether console logging is enabled. + Enabled bool `json:"enabled"` +} + +// FileLoggingConfig describes the configuration options for logging to file. Note that this not being used right now +// but will be added to LoggingConfig down the line +// TODO: Update when implementing a structured logging solution +type FileLoggingConfig struct { + // LogDirectory describes what directory log files should be outputted in. LogDirectory being a non-empty string + // is equivalent to enabling file logging. + LogDirectory bool `json:"logDirectory"` +} + // ReadProjectConfigFromFile reads a JSON-serialized ProjectConfig from a provided file path. // Returns the ProjectConfig if it succeeds, or an error if one occurs. func ReadProjectConfigFromFile(path string) (*ProjectConfig, error) { // Read our project configuration file data - fmt.Printf("Reading configuration file: %s\n", path) b, err := os.ReadFile(path) if err != nil { return nil, err @@ -261,5 +291,11 @@ func (p *ProjectConfig) Validate() error { return errors.New("project configuration must specify test name prefixes if property testing is enabled") } } + + // Ensure that the log level is a valid one + if _, err := zerolog.ParseLevel(p.Logging.Level.String()); err != nil { + return err + } + return nil } diff --git a/fuzzing/config/config_defaults.go b/fuzzing/config/config_defaults.go index 3a26d3d3..2a6e92f0 100644 --- a/fuzzing/config/config_defaults.go +++ b/fuzzing/config/config_defaults.go @@ -3,6 +3,7 @@ package config import ( testChainConfig "github.com/crytic/medusa/chain/config" "github.com/crytic/medusa/compilation" + "github.com/rs/zerolog" ) // GetDefaultProjectConfig obtains a default configuration for a project. It populates a default compilation config @@ -79,6 +80,10 @@ func GetDefaultProjectConfig(platform string) (*ProjectConfig, error) { TestChainConfig: *chainConfig, }, Compilation: compilationConfig, + Logging: LoggingConfig{ + Level: zerolog.InfoLevel, + LogDirectory: "", + }, } // Return the project configuration diff --git a/fuzzing/corpus/corpus.go b/fuzzing/corpus/corpus.go index 28255579..827a3f58 100644 --- a/fuzzing/corpus/corpus.go +++ b/fuzzing/corpus/corpus.go @@ -6,6 +6,8 @@ import ( "github.com/crytic/medusa/chain" "github.com/crytic/medusa/fuzzing/calls" "github.com/crytic/medusa/fuzzing/coverage" + "github.com/crytic/medusa/logging" + "github.com/crytic/medusa/logging/colors" "github.com/crytic/medusa/utils/randomutils" "github.com/ethereum/go-ethereum/common" "github.com/google/uuid" @@ -51,6 +53,9 @@ type Corpus struct { // callSequencesLock provides thread synchronization to prevent concurrent access errors into // callSequences. callSequencesLock sync.Mutex + + // logger describes the Corpus's log object that can be used to log important events + logger *logging.Logger } // NewCorpus initializes a new Corpus object, reading artifacts from the provided directory. If the directory refers @@ -64,6 +69,7 @@ func NewCorpus(corpusDirectory string) (*Corpus, error) { immutableSequenceFiles: newCorpusDirectory[calls.CallSequence](""), testResultSequenceFiles: newCorpusDirectory[calls.CallSequence](""), unexecutedCallSequences: make([]calls.CallSequence, 0), + logger: logging.GlobalLogger.NewSubLogger("module", "corpus"), } // If we have a corpus directory set, parse our call sequences. @@ -216,7 +222,7 @@ func (c *Corpus) initializeSequences(sequenceFiles *corpusDirectory[calls.CallSe } c.unexecutedCallSequences = append(c.unexecutedCallSequences, sequence) } else { - fmt.Printf("corpus item '%v' disabled due to error when replaying it: %v\n", sequenceFileData.fileName, sequenceInvalidError) + c.logger.Warn("Corpus item ", colors.Bold, sequenceFileData.fileName, colors.Reset, " disabled due to error when replaying it", sequenceInvalidError) } // Revert chain state to our starting point to test the next sequence. diff --git a/fuzzing/coverage/coverage_tracer.go b/fuzzing/coverage/coverage_tracer.go index 4882c640..4652fde4 100644 --- a/fuzzing/coverage/coverage_tracer.go +++ b/fuzzing/coverage/coverage_tracer.go @@ -1,8 +1,8 @@ package coverage import ( - "fmt" "github.com/crytic/medusa/chain/types" + "github.com/crytic/medusa/logging" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/core/vm" "math/big" @@ -92,14 +92,14 @@ func (t *CoverageTracer) CaptureEnd(output []byte, gasUsed uint64, err error) { if err != nil { _, revertCoverageErr := t.callFrameStates[t.callDepth].pendingCoverageMap.RevertAll() if revertCoverageErr != nil { - panic(revertCoverageErr) + logging.GlobalLogger.Panic("Coverage tracer failed to update revert coverage map during capture end", revertCoverageErr) } } // Commit all our coverage maps up one call frame. _, _, coverageUpdateErr := t.coverageMaps.Update(t.callFrameStates[t.callDepth].pendingCoverageMap) if coverageUpdateErr != nil { - panic(fmt.Sprintf("coverage tracer failed to update coverage map during capture exit: %v", coverageUpdateErr)) + logging.GlobalLogger.Panic("Coverage tracer failed to update coverage map during capture end", coverageUpdateErr) } // Pop the state tracking struct for this call frame off the stack. @@ -124,14 +124,14 @@ func (t *CoverageTracer) CaptureExit(output []byte, gasUsed uint64, err error) { if err != nil { _, revertCoverageErr := t.callFrameStates[t.callDepth].pendingCoverageMap.RevertAll() if revertCoverageErr != nil { - panic(revertCoverageErr) + logging.GlobalLogger.Panic("Coverage tracer failed to update revert coverage map during capture exit", revertCoverageErr) } } // Commit all our coverage maps up one call frame. _, _, coverageUpdateErr := t.callFrameStates[t.callDepth-1].pendingCoverageMap.Update(t.callFrameStates[t.callDepth].pendingCoverageMap) if coverageUpdateErr != nil { - panic(fmt.Sprintf("coverage tracer failed to update coverage map during capture exit: %v", coverageUpdateErr)) + logging.GlobalLogger.Panic("Coverage tracer failed to update coverage map during capture exit", coverageUpdateErr) } // Pop the state tracking struct for this call frame off the stack. @@ -157,7 +157,7 @@ func (t *CoverageTracer) CaptureState(pc uint64, op vm.OpCode, gas, cost uint64, // Record coverage for this location in our map. _, coverageUpdateErr := callFrameState.pendingCoverageMap.SetAt(scope.Contract.Address(), *callFrameState.lookupHash, len(scope.Contract.Code), pc) if coverageUpdateErr != nil { - panic(fmt.Sprintf("coverage tracer failed to update coverage map while tracing state: %v", coverageUpdateErr)) + logging.GlobalLogger.Panic("Coverage tracer failed to update coverage map while tracing state", coverageUpdateErr) } } } diff --git a/fuzzing/executiontracer/execution_trace.go b/fuzzing/executiontracer/execution_trace.go index fcca4d24..a021de9d 100644 --- a/fuzzing/executiontracer/execution_trace.go +++ b/fuzzing/executiontracer/execution_trace.go @@ -6,6 +6,8 @@ import ( "github.com/crytic/medusa/compilation/abiutils" "github.com/crytic/medusa/fuzzing/contracts" "github.com/crytic/medusa/fuzzing/valuegeneration" + "github.com/crytic/medusa/logging" + "github.com/crytic/medusa/logging/colors" "github.com/ethereum/go-ethereum/accounts/abi" coreTypes "github.com/ethereum/go-ethereum/core/types" "github.com/ethereum/go-ethereum/core/vm" @@ -32,13 +34,16 @@ func newExecutionTrace(contracts contracts.Contracts) *ExecutionTrace { } } -// generateCallFrameEnterString generates a header string to print for the given call frame. It contains -// information about the invoked call. -// Returns the header string -func (t *ExecutionTrace) generateCallFrameEnterString(callFrame *CallFrame) string { - // Define some strings that represent our current call frame +// generateCallFrameEnterElements generates a list of elements describing top level information about this call frame. +// This list of elements will hold information about what kind of call it is, wei sent, what method is called, and more. +// Additionally, the list may also hold formatting options for console output. +func (t *ExecutionTrace) generateCallFrameEnterElements(callFrame *CallFrame) []any { + // Create list of elements + elements := make([]any, 0) + + // Define some strings and objects that represent our current call frame var ( - callType = "call" + callType = []any{colors.BlueBold, "[call] ", colors.Reset} proxyContractName = "" codeContractName = "" methodName = "" @@ -46,13 +51,16 @@ func (t *ExecutionTrace) generateCallFrameEnterString(callFrame *CallFrame) stri err error ) - // If this is a contract creation, use a different prefix + // If this is a contract creation or proxy call, use different formatting for call type if callFrame.IsContractCreation() { - callType = "creation" + callType = []any{colors.YellowBold, "[creation] ", colors.Reset} } else if callFrame.IsProxyCall() { - callType = "proxy call" + callType = []any{colors.CyanBold, "[proxy call] ", colors.Reset} } + // Append the formatted call type information to the list of elements + elements = append(elements, callType...) + // Resolve our contract names, as well as our method and its name from the code contract. if callFrame.ToContractAbi != nil { proxyContractName = callFrame.ToContractName @@ -103,25 +111,33 @@ func (t *ExecutionTrace) generateCallFrameEnterString(callFrame *CallFrame) stri // Generate the message we wish to output finally, using all these display string components. // If we executed code, attach additional context such as the contract name, method, etc. + var callInfo string if callFrame.IsProxyCall() { if callFrame.ExecutedCode { - return fmt.Sprintf("[%v] %v -> %v.%v(%v) (addr=%v, code=%v, value=%v, sender=%v)", callType, proxyContractName, codeContractName, methodName, *inputArgumentsDisplayText, callFrame.ToAddress.String(), callFrame.CodeAddress.String(), callFrame.CallValue, callFrame.SenderAddress.String()) + callInfo = fmt.Sprintf("%v -> %v.%v(%v) (addr=%v, code=%v, value=%v, sender=%v)", proxyContractName, codeContractName, methodName, *inputArgumentsDisplayText, callFrame.ToAddress.String(), callFrame.CodeAddress.String(), callFrame.CallValue, callFrame.SenderAddress.String()) } else { - return fmt.Sprintf("[%v] (addr=%v, value=%v, sender=%v)", callType, callFrame.ToAddress.String(), callFrame.CallValue, callFrame.SenderAddress.String()) + callInfo = fmt.Sprintf("(addr=%v, value=%v, sender=%v)", callFrame.ToAddress.String(), callFrame.CallValue, callFrame.SenderAddress.String()) } } else { if callFrame.ExecutedCode { - return fmt.Sprintf("[%v] %v.%v(%v) (addr=%v, value=%v, sender=%v)", callType, codeContractName, methodName, *inputArgumentsDisplayText, callFrame.ToAddress.String(), callFrame.CallValue, callFrame.SenderAddress.String()) + callInfo = fmt.Sprintf("%v.%v(%v) (addr=%v, value=%v, sender=%v)", codeContractName, methodName, *inputArgumentsDisplayText, callFrame.ToAddress.String(), callFrame.CallValue, callFrame.SenderAddress.String()) } else { - return fmt.Sprintf("[%v] (addr=%v, value=%v, sender=%v)", callType, callFrame.ToAddress.String(), callFrame.CallValue, callFrame.SenderAddress.String()) + callInfo = fmt.Sprintf("(addr=%v, value=%v, sender=%v)", callFrame.ToAddress.String(), callFrame.CallValue, callFrame.SenderAddress.String()) } } + + // Add call information to the elements + elements = append(elements, callInfo, "\n") + + return elements } -// generateCallFrameExitString generates a footer string to print for the given call frame. It contains -// result information about the call. -// Returns the footer string. -func (t *ExecutionTrace) generateCallFrameExitString(callFrame *CallFrame) string { +// generateCallFrameExitElements generates a list of elements describing the return data of the call frame (e.g. +// traditional return data, assertion failure, revert data, etc.). Additionally, the list may also hold formatting options for console output. +func (t *ExecutionTrace) generateCallFrameExitElements(callFrame *CallFrame) []any { + // Create list of elements + elements := make([]any, 0) + // Define some strings that represent our current call frame var method *abi.Method @@ -158,19 +174,22 @@ func (t *ExecutionTrace) generateCallFrameExitString(callFrame *CallFrame) strin // Wrap our return message and output it at the end. if callFrame.ReturnError == nil { - return fmt.Sprintf("[return (%v)]", *outputArgumentsDisplayText) + elements = append(elements, colors.GreenBold, fmt.Sprintf("[return (%v)]", *outputArgumentsDisplayText), colors.Reset, "\n") + return elements } // Try to resolve a panic message and check if it signals a failed assertion. panicCode := abiutils.GetSolidityPanicCode(callFrame.ReturnError, callFrame.ReturnData, true) if panicCode != nil { - return "[" + abiutils.GetPanicReason(panicCode.Uint64()) + "]" + elements = append(elements, colors.RedBold, fmt.Sprintf("[%v]", abiutils.GetPanicReason(panicCode.Uint64())), colors.Reset, "\n") + return elements } // Try to resolve an assertion failed panic code. errorMessage := abiutils.GetSolidityRevertErrorString(callFrame.ReturnError, callFrame.ReturnData) if errorMessage != nil { - return fmt.Sprintf("[revert ('%v')]", *errorMessage) + elements = append(elements, colors.RedBold, fmt.Sprintf("[revert ('%v')]", *errorMessage), colors.Reset, "\n") + return elements } // Try to unpack a custom Solidity error from the return values. @@ -178,23 +197,28 @@ func (t *ExecutionTrace) generateCallFrameExitString(callFrame *CallFrame) strin if matchedCustomError != nil { customErrorArgsDisplayText, err := valuegeneration.EncodeABIArgumentsToString(matchedCustomError.Inputs, unpackedCustomErrorArgs) if err == nil { - return fmt.Sprintf("[revert (error: %v(%v))]", matchedCustomError.Name, customErrorArgsDisplayText) + elements = append(elements, colors.RedBold, fmt.Sprintf("[revert (error: %v(%v))]", matchedCustomError.Name, customErrorArgsDisplayText), colors.Reset, "\n") + return elements } } // Check if this is a generic revert. if callFrame.ReturnError == vm.ErrExecutionReverted { - return "[revert]" + elements = append(elements, colors.RedBold, "[revert]", colors.Reset, "\n") + return elements } // If we could not resolve any custom error, we simply print out the generic VM error message. - return fmt.Sprintf("[vm error ('%v')]", callFrame.ReturnError.Error()) + elements = append(elements, colors.RedBold, fmt.Sprintf("[vm error ('%v')]", callFrame.ReturnError.Error()), colors.Reset, "\n") + return elements } -// generateEventEmittedString generates a string used to express an event emission. It contains information about an -// event log. -// Returns a string representing an event emission. -func (t *ExecutionTrace) generateEventEmittedString(callFrame *CallFrame, eventLog *coreTypes.Log) string { +// generateEventEmittedElements generates a list of elements used to express an event emission. It contains information about an +// event log such as the topics and the event data. Additionally, the list may also hold formatting options for console output. +func (t *ExecutionTrace) generateEventEmittedElements(callFrame *CallFrame, eventLog *coreTypes.Log) []any { + // Create list of elements + elements := make([]any, 0) + // If this is an event log, match it in our contract's ABI. var eventDisplayText *string @@ -235,26 +259,27 @@ func (t *ExecutionTrace) generateEventEmittedString(callFrame *CallFrame, eventL } // Finally, add our output line with this event data to it. - return fmt.Sprintf("[event] %v", *eventDisplayText) + elements = append(elements, colors.MagentaBold, "[event] ", colors.Reset, *eventDisplayText, "\n") + return elements } -// generateStringsForCallFrame generates indented strings for a given call frame and its children. -// Returns the list of strings, to be joined by new line separators. -func (t *ExecutionTrace) generateStringsForCallFrame(currentDepth int, callFrame *CallFrame) []string { - // Create our resulting strings array - var outputLines []string +// generateElementsForCallFrame generates a list of elements for a given call frame and its children. Additionally, +// the list may also hold formatting options for console output. +func (t *ExecutionTrace) generateElementsForCallFrame(currentDepth int, callFrame *CallFrame) []any { + // Create list of elements + elements := make([]any, 0) // Create our current call line prefix (indented by call depth) - prefix := strings.Repeat("\t", currentDepth) + " -> " + prefix := strings.Repeat("\t", currentDepth) + " => " // If we're printing the root frame, add the overall execution trace header. if currentDepth == 0 { - outputLines = append(outputLines, prefix+"[Execution Trace]") + elements = append(elements, colors.Bold, "[Execution Trace]", colors.Reset, "\n") } - // Add the call frame enter header - header := prefix + t.generateCallFrameEnterString(callFrame) - outputLines = append(outputLines, header) + // Add the call frame enter header elements + elements = append(elements, prefix) + elements = append(elements, t.generateCallFrameEnterElements(callFrame)...) // Now that the header has been printed, create our indent level to express everything that // happened under it. @@ -268,31 +293,40 @@ func (t *ExecutionTrace) generateStringsForCallFrame(currentDepth int, callFrame for _, operation := range callFrame.Operations { if childCallFrame, ok := operation.(*CallFrame); ok { // If this is a call frame being entered, generate information recursively. - childOutputLines := t.generateStringsForCallFrame(currentDepth+1, childCallFrame) - outputLines = append(outputLines, childOutputLines...) + childOutputLines := t.generateElementsForCallFrame(currentDepth+1, childCallFrame) + elements = append(elements, childOutputLines...) } else if eventLog, ok := operation.(*coreTypes.Log); ok { // If an event log was emitted, add a message for it. - eventMessage := prefix + t.generateEventEmittedString(callFrame, eventLog) - outputLines = append(outputLines, eventMessage) + elements = append(elements, prefix) + elements = append(elements, t.generateEventEmittedElements(callFrame, eventLog)...) } } // If we self-destructed, add a message for it before our footer. if callFrame.SelfDestructed { - outputLines = append(outputLines, fmt.Sprintf("%v[selfdestruct]", prefix)) + elements = append(elements, prefix, colors.MagentaBold, "[selfdestruct]", colors.Reset, "\n") } // Add the call frame exit footer - footer := prefix + t.generateCallFrameExitString(callFrame) - outputLines = append(outputLines, footer) + elements = append(elements, prefix) + elements = append(elements, t.generateCallFrameExitElements(callFrame)...) } - // Return our output lines - return outputLines + // Return our elements + return elements +} + +// Log returns a logging.LogBuffer that represents this execution trace. This buffer will be passed to the underlying +// logger which will format it accordingly for console or file. +func (t *ExecutionTrace) Log() *logging.LogBuffer { + buffer := logging.NewLogBuffer() + buffer.Append(t.generateElementsForCallFrame(0, t.TopLevelCallFrame)...) + return buffer } -// String returns a string representation of the execution trace. +// String returns the string representation of this execution trace func (t *ExecutionTrace) String() string { - outputLines := t.generateStringsForCallFrame(0, t.TopLevelCallFrame) - return strings.Join(outputLines, "\n") + // Internally, we just call the log function, get the list of elements and create their non-colorized string representation + // Might be useful for 3rd party apps + return t.Log().String() } diff --git a/fuzzing/fuzzer.go b/fuzzing/fuzzer.go index 2ad2d2f6..e64a7ba2 100644 --- a/fuzzing/fuzzer.go +++ b/fuzzing/fuzzer.go @@ -4,10 +4,16 @@ import ( "context" "fmt" "github.com/crytic/medusa/fuzzing/coverage" + "github.com/crytic/medusa/logging" + "github.com/crytic/medusa/logging/colors" + "github.com/rs/zerolog" + "github.com/rs/zerolog/pkgerrors" + "io" "math/big" "math/rand" "path/filepath" "sort" + "strconv" "strings" "sync" "time" @@ -74,26 +80,53 @@ type Fuzzer struct { // Hooks describes the replaceable functions used by the Fuzzer. Hooks FuzzerHooks + + // logger describes the Fuzzer's log object that can be used to log important events + logger *logging.Logger } // NewFuzzer returns an instance of a new Fuzzer provided a project configuration, or an error if one is encountered // while initializing the code. func NewFuzzer(config config.ProjectConfig) (*Fuzzer, error) { + // Create the global logger, set some global logging parameters, and enable terminal coloring + logging.GlobalLogger = logging.NewLogger(config.Logging.Level, true, make([]io.Writer, 0)...) + zerolog.ErrorStackMarshaler = pkgerrors.MarshalStack + zerolog.TimeFieldFormat = zerolog.TimeFormatUnix + + // If the log directory is a non-empty string, create a file for file logging + if config.Logging.LogDirectory != "" { + // Filename will be the "log-current_unix_timestamp.log" + filename := "log-" + strconv.FormatInt(time.Now().Unix(), 10) + ".log" + // Create the file + file, err := utils.CreateFile(config.Logging.LogDirectory, filename) + if err != nil { + logging.GlobalLogger.Error("Failed to create log file", err) + return nil, err + } + logging.GlobalLogger.AddWriter(file, logging.UNSTRUCTURED) + } + + // Get the fuzzer's custom sub-logger + logger := logging.GlobalLogger.NewSubLogger("module", "fuzzer") + // Validate our provided config err := config.Validate() if err != nil { + logger.Error("Invalid configuration", err) return nil, err } // Parse the senders addresses from our account config. senders, err := utils.HexStringsToAddresses(config.Fuzzing.SenderAddresses) if err != nil { + logger.Error("Invalid sender address(es)", err) return nil, err } // Parse the deployer address from our account config deployer, err := utils.HexStringToAddress(config.Fuzzing.DeployerAddress) if err != nil { + logger.Error("Invalid deployer address", err) return nil, err } @@ -112,6 +145,7 @@ func NewFuzzer(config config.ProjectConfig) (*Fuzzer, error) { ChainSetupFunc: chainSetupFromCompilations, CallSequenceTestFuncs: make([]CallSequenceTestFunc, 0), }, + logger: logger, } // Add our sender and deployer addresses to the base value set for the value generator, so they will be used as @@ -124,12 +158,12 @@ func NewFuzzer(config config.ProjectConfig) (*Fuzzer, error) { // If we have a compilation config if fuzzer.config.Compilation != nil { // Compile the targets specified in the compilation config - fmt.Printf("Compiling targets (platform '%s') ...\n", fuzzer.config.Compilation.Platform) - compilations, compilationOutput, err := (*fuzzer.config.Compilation).Compile() + fuzzer.logger.Info("Compiling targets with ", colors.Bold, fuzzer.config.Compilation.Platform, colors.Reset) + compilations, _, err := (*fuzzer.config.Compilation).Compile() if err != nil { + fuzzer.logger.Error("Failed to compile target", err) return nil, err } - fmt.Printf("%s", compilationOutput) // Add our compilation targets fuzzer.AddCompilationTargets(compilations) @@ -143,8 +177,8 @@ func NewFuzzer(config config.ProjectConfig) (*Fuzzer, error) { attachAssertionTestCaseProvider(fuzzer) } if fuzzer.config.Fuzzing.Testing.OptimizationTesting.Enabled { - // TODO: Make this is a warning in the logging PR - fmt.Printf("warning: currently optimization mode's call sequence shrinking is inefficient. this may lead to minor performance issues") + // TODO: Remove this warning when call sequence shrinking is improved + fuzzer.logger.Warn("Currently, optimization mode's call sequence shrinking is inefficient; this may lead to minor performance issues") attachOptimizationTestCaseProvider(fuzzer) } return fuzzer, nil @@ -221,7 +255,7 @@ func (f *Fuzzer) ReportTestCaseFinished(testCase TestCase) { // We only log here if we're not configured to stop on the first test failure. This is because the fuzzer prints // results on exit, so we avoid duplicate messages. if !f.config.Fuzzing.Testing.StopOnFailedTest { - fmt.Printf("\n[%s] %s\n%s\n\n", testCase.Status(), testCase.Name(), testCase.Message()) + f.logger.Info(testCase.LogMessage().Elements()...) } // If the config specifies, we stop after the first failed test reported. @@ -255,7 +289,7 @@ func (f *Fuzzer) AddCompilationTargets(compilations []compilationTypes.Compilati // Cache all of our source code if it hasn't been already. err := compilation.CacheSourceCode() if err != nil { - fmt.Printf("Warning: could not cache compilation source file data due to error: %v", err) + f.logger.Warn("Failed to cache compilation source file data", err) } } } @@ -464,7 +498,7 @@ func (f *Fuzzer) spawnWorkersLoop(baseTestChain *chain.TestChain) error { working := !utils.CheckContextDone(f.ctx) // Log that we are about to create the workers and start fuzzing - fmt.Printf("Creating %d workers ...\n", f.config.Fuzzing.Workers) + f.logger.Info("Creating ", colors.Bold, f.config.Fuzzing.Workers, colors.Reset, " workers...") var err error for err == nil && working { // Send an item into our channel to queue up a spot. This will block us if we hit capacity until a worker @@ -562,13 +596,14 @@ func (f *Fuzzer) Start() error { // If we set a timeout, create the timeout context now, as we're about to begin fuzzing. if f.config.Fuzzing.Timeout > 0 { - fmt.Printf("Running with timeout of %d seconds\n", f.config.Fuzzing.Timeout) + f.logger.Info("Running with a timeout of ", colors.Bold, f.config.Fuzzing.Timeout, " seconds") f.ctx, f.ctxCancelFunc = context.WithTimeout(f.ctx, time.Duration(f.config.Fuzzing.Timeout)*time.Second) } // Set up the corpus f.corpus, err = corpus.NewCorpus(f.config.Fuzzing.CorpusDirectory) if err != nil { + f.logger.Error("Failed to create the corpus", err) return err } @@ -584,18 +619,21 @@ func (f *Fuzzer) Start() error { // Create our test chain baseTestChain, err := f.createTestChain() if err != nil { + f.logger.Error("Failed to create the test chain", err) return err } // Set it up with our deployment/setup strategy defined by the fuzzer. err = f.Hooks.ChainSetupFunc(f, baseTestChain) if err != nil { + f.logger.Error("Failed to initialize the test chain", err) return err } // Initialize our coverage maps by measuring the coverage we get from the corpus. err = f.corpus.Initialize(baseTestChain, f.contractDefinitions) if err != nil { + f.logger.Error("Failed to initialize the corpus", err) return err } @@ -605,16 +643,22 @@ func (f *Fuzzer) Start() error { // Publish a fuzzer starting event. err = f.Events.FuzzerStarting.Publish(FuzzerStartingEvent{Fuzzer: f}) if err != nil { + f.logger.Error("FuzzerStarting event subscriber returned an error", err) return err } // If StopOnNoTests is true and there are no test cases, then throw an error if f.config.Fuzzing.Testing.StopOnNoTests && len(f.testCases) == 0 { - return fmt.Errorf("no tests of any kind (assertion/property/optimization/custom) have been identified for fuzzing") + err = fmt.Errorf("no tests of any kind (assertion/property/optimization/custom) have been identified for fuzzing") + f.logger.Error("Failed to start fuzzer", err) + return err } // Run the main worker loop err = f.spawnWorkersLoop(baseTestChain) + if err != nil { + f.logger.Error("Encountered an error in the main fuzzing loop", err) + } // NOTE: After this point, we capture errors but do not return immediately, as we want to exit gracefully. @@ -622,8 +666,9 @@ func (f *Fuzzer) Start() error { // previous error, as we don't want to lose corpus entries. if f.config.Fuzzing.CoverageEnabled { corpusFlushErr := f.corpus.Flush() - if err == nil { + if err == nil && corpusFlushErr != nil { err = corpusFlushErr + f.logger.Info("Failed to flush the corpus", err) } } @@ -631,6 +676,7 @@ func (f *Fuzzer) Start() error { fuzzerStoppingErr := f.Events.FuzzerStopping.Publish(FuzzerStoppingEvent{Fuzzer: f, err: err}) if err == nil && fuzzerStoppingErr != nil { err = fuzzerStoppingErr + f.logger.Error("FuzzerStopping event subscriber returned an error", err) } // Print our results on exit. @@ -640,7 +686,7 @@ func (f *Fuzzer) Start() error { if err == nil && f.config.Fuzzing.CorpusDirectory != "" { coverageReportPath := filepath.Join(f.config.Fuzzing.CorpusDirectory, "coverage_report.html") err = coverage.GenerateReport(f.compilations, f.corpus.CoverageMaps(), coverageReportPath) - fmt.Printf("coverage report saved to file: %v\n", coverageReportPath) + f.logger.Info("Coverage report saved to file: ", colors.Bold, coverageReportPath, colors.Reset) } // Return any encountered error. @@ -677,15 +723,12 @@ func (f *Fuzzer) printMetricsLoop() { secondsSinceLastUpdate := time.Since(lastPrintedTime).Seconds() // Print a metrics update - fmt.Printf( - "fuzz: elapsed: %s, call: %d (%d/sec), seq/s: %d, resets/s: %d, cov: %d\n", - time.Since(startTime).Round(time.Second), - callsTested, - uint64(float64(new(big.Int).Sub(callsTested, lastCallsTested).Uint64())/secondsSinceLastUpdate), - uint64(float64(new(big.Int).Sub(sequencesTested, lastSequencesTested).Uint64())/secondsSinceLastUpdate), - uint64(float64(new(big.Int).Sub(workerStartupCount, lastWorkerStartupCount).Uint64())/secondsSinceLastUpdate), - f.corpus.ActiveMutableSequenceCount(), - ) + f.logger.Info(colors.Bold, "fuzz: ", colors.Reset, + "elapsed: ", colors.Bold, time.Since(startTime).Round(time.Second).String(), colors.Reset, + ", calls: ", colors.Bold, fmt.Sprintf("%d (%d/sec)", callsTested, uint64(float64(new(big.Int).Sub(callsTested, lastCallsTested).Uint64())/secondsSinceLastUpdate)), colors.Reset, + ", seq/s: ", colors.Bold, fmt.Sprintf("%d", uint64(float64(new(big.Int).Sub(sequencesTested, lastSequencesTested).Uint64())/secondsSinceLastUpdate)), colors.Reset, + ", resets/s: ", colors.Bold, fmt.Sprintf("%d", uint64(float64(new(big.Int).Sub(workerStartupCount, lastWorkerStartupCount).Uint64())/secondsSinceLastUpdate)), colors.Reset, + ", coverage: ", colors.Bold, fmt.Sprintf("%d", f.corpus.ActiveMutableSequenceCount()), colors.Reset) // Update our delta tracking metrics lastPrintedTime = time.Now() @@ -696,7 +739,7 @@ func (f *Fuzzer) printMetricsLoop() { // If we reached our transaction threshold, halt testLimit := f.config.Fuzzing.TestLimit if testLimit > 0 && (!callsTested.IsUint64() || callsTested.Uint64() >= testLimit) { - fmt.Printf("transaction test limit reached, halting now ...\n") + f.logger.Info("Transaction test limit reached, halting now...") f.Stop() break } @@ -736,17 +779,9 @@ func (f *Fuzzer) printExitingResults() { ) // Print the results of each individual test case. - fmt.Printf("\n") - fmt.Printf("Fuzzer stopped, test results follow below ...\n") + f.logger.Info("Fuzzer stopped, test results follow below ...") for _, testCase := range f.testCases { - // Obtain the test case message. If it is a non-empty string, we format our output for it specially. - // Otherwise, we exclude it. - msg := strings.TrimSpace(testCase.Message()) - if msg != "" { - fmt.Printf("[%s] %s\n%s\n\n", testCase.Status(), strings.TrimSpace(testCase.Name()), msg) - } else { - fmt.Printf("[%s] %s\n", testCase.Status(), testCase.Name()) - } + f.logger.Info(testCase.LogMessage().Elements()...) // Tally our pass/fail count. if testCase.Status() == TestCaseStatusPassed { @@ -757,6 +792,5 @@ func (f *Fuzzer) printExitingResults() { } // Print our final tally of test statuses. - fmt.Printf("\n") - fmt.Printf("%d test(s) passed, %d test(s) failed\n", testCountPassed, testCountFailed) + f.logger.Info("Test summary: ", colors.GreenBold, testCountPassed, colors.Reset, " test(s) passed, ", colors.RedBold, testCountFailed, colors.Reset, " test(s) failed") } diff --git a/fuzzing/fuzzer_test.go b/fuzzing/fuzzer_test.go index 7a80786f..42ff13c5 100644 --- a/fuzzing/fuzzer_test.go +++ b/fuzzing/fuzzer_test.go @@ -144,8 +144,8 @@ func TestAssertionsAndProperties(t *testing.T) { }) } -// TestOptimizationsSolving runs a test to ensure that optimization mode works as expected -func TestOptimizationsSolving(t *testing.T) { +// TestOptimizationMode runs a test to ensure that optimization mode works as expected +func TestOptimizationMode(t *testing.T) { filePaths := []string{ "testdata/contracts/optimizations/optimize.sol", } @@ -407,7 +407,7 @@ func TestExecutionTraces(t *testing.T) { assert.NotNilf(t, lastCall.ExecutionTrace, "expected to have an execution trace attached to call sequence for this test") // Get the execution trace message - executionTraceMsg := lastCall.ExecutionTrace.String() + executionTraceMsg := lastCall.ExecutionTrace.Log().String() // Verify it contains all expected strings for _, expectedTraceMessage := range expectedTraceMessages { diff --git a/fuzzing/test_case.go b/fuzzing/test_case.go index d5e6a546..6be040e7 100644 --- a/fuzzing/test_case.go +++ b/fuzzing/test_case.go @@ -2,6 +2,7 @@ package fuzzing import ( "github.com/crytic/medusa/fuzzing/calls" + "github.com/crytic/medusa/logging" ) // TestCaseStatus defines the status of a TestCase as a string-represented enum. @@ -31,7 +32,11 @@ type TestCase interface { // Name describes the name of the test case. Name() string - // Message obtains a text-based printable message which describes the test result. + // LogMessage obtains a logging.LogBuffer that represents the result of the TestCase. This buffer can be passed to a logger for + // console or file logging. + LogMessage() *logging.LogBuffer + + // Message obtains a text-based printable message which describes the result of the AssertionTestCase. Message() string // ID obtains a unique identifier for a test result. If the same test fails, this ID should match for both diff --git a/fuzzing/test_case_assertion.go b/fuzzing/test_case_assertion.go index 354c2161..7cdf3bb3 100644 --- a/fuzzing/test_case_assertion.go +++ b/fuzzing/test_case_assertion.go @@ -2,6 +2,8 @@ package fuzzing import ( "fmt" + "github.com/crytic/medusa/logging" + "github.com/crytic/medusa/logging/colors" "strings" "github.com/crytic/medusa/fuzzing/calls" @@ -37,18 +39,27 @@ func (t *AssertionTestCase) Name() string { return fmt.Sprintf("Assertion Test: %s.%s", t.targetContract.Name(), t.targetMethod.Sig) } -// Message obtains a text-based printable message which describes the test result. -func (t *AssertionTestCase) Message() string { +// LogMessage obtains a buffer that represents the result of the AssertionTestCase. This buffer can be passed to a logger for +// console or file logging. +func (t *AssertionTestCase) LogMessage() *logging.LogBuffer { // If the test failed, return a failure message. + buffer := logging.NewLogBuffer() if t.Status() == TestCaseStatusFailed { - return fmt.Sprintf( - "Test for method \"%s.%s\" failed after the following call sequence resulted in an assertion:\n%s", - t.targetContract.Name(), - t.targetMethod.Sig, - t.CallSequence().String(), - ) + buffer.Append(colors.RedBold, fmt.Sprintf("[%s] ", t.Status()), colors.Bold, t.Name(), colors.Reset, "\n") + buffer.Append(fmt.Sprintf("Test for method \"%s.%s\" resulted in an assertion failure after the following call sequence:\n", t.targetContract.Name(), t.targetMethod.Sig)) + buffer.Append(colors.Bold, "[Call Sequence]", colors.Reset, "\n") + buffer.Append(t.CallSequence().Log().Elements()...) + return buffer } - return "" + + buffer.Append(colors.GreenBold, fmt.Sprintf("[%s] ", t.Status()), colors.Bold, t.Name(), colors.Reset) + return buffer +} + +// Message obtains a text-based printable message which describes the result of the AssertionTestCase. +func (t *AssertionTestCase) Message() string { + // Internally, we just call log message and convert it to a string. This can be useful for 3rd party apps + return t.LogMessage().String() } // ID obtains a unique identifier for a test result. diff --git a/fuzzing/test_case_optimization.go b/fuzzing/test_case_optimization.go index 3110c0ad..8b3f4e41 100644 --- a/fuzzing/test_case_optimization.go +++ b/fuzzing/test_case_optimization.go @@ -5,6 +5,8 @@ import ( "github.com/crytic/medusa/fuzzing/calls" "github.com/crytic/medusa/fuzzing/contracts" "github.com/crytic/medusa/fuzzing/executiontracer" + "github.com/crytic/medusa/logging" + "github.com/crytic/medusa/logging/colors" "github.com/ethereum/go-ethereum/accounts/abi" "math/big" "strings" @@ -45,25 +47,29 @@ func (t *OptimizationTestCase) Name() string { return fmt.Sprintf("Optimization Test: %s.%s", t.targetContract.Name(), t.targetMethod.Sig) } -// Message obtains a text-based printable message which describes the test result. -func (t *OptimizationTestCase) Message() string { - // We print final value in case the test case passed for optimization test - if t.Status() == TestCaseStatusPassed { - msg := fmt.Sprintf( - "Optimization test \"%s.%s\" resulted in the maximum value: %s with the following sequence:\n%s", - t.targetContract.Name(), - t.targetMethod.Sig, - t.value, - t.CallSequence().String(), - ) - // If an execution trace is attached then add it to the message - if t.optimizationTestTrace != nil { - // TODO: Improve formatting in logging PR - msg += fmt.Sprintf("\nOptimization test execution trace:\n%s", t.optimizationTestTrace.String()) - } - return msg +// LogMessage obtains a buffer that represents the result of the AssertionTestCase. This buffer can be passed to a logger for +// console or file logging. +func (t *OptimizationTestCase) LogMessage() *logging.LogBuffer { + buffer := logging.NewLogBuffer() + + // Note that optimization tests will always pass + buffer.Append(colors.GreenBold, fmt.Sprintf("[%s] ", t.Status()), colors.Bold, t.Name(), colors.Reset, "\n") + buffer.Append(fmt.Sprintf("Test for method \"%s.%s\" resulted in the maximum value: ", t.targetContract.Name(), t.targetMethod.Sig)) + buffer.Append(colors.Bold, t.value, colors.Reset, "\n") + buffer.Append(colors.Bold, "[Call Sequence]", colors.Reset, "\n") + buffer.Append(t.CallSequence().Log().Elements()...) + // If an execution trace is attached then add it to the message + if t.optimizationTestTrace != nil { + buffer.Append(colors.Bold, "[Optimization Test Execution Trace]", colors.Reset, "\n") + buffer.Append(t.optimizationTestTrace.Log().Elements()...) } - return "" + return buffer +} + +// Message obtains a text-based printable message which describes the result of the OptimizationTestCase. +func (t *OptimizationTestCase) Message() string { + // Internally, we just call log message and convert it to a string. This can be useful for 3rd party apps + return t.LogMessage().String() } // ID obtains a unique identifier for a test result. diff --git a/fuzzing/test_case_optimization_provider.go b/fuzzing/test_case_optimization_provider.go index 622aa155..ba5ab258 100644 --- a/fuzzing/test_case_optimization_provider.go +++ b/fuzzing/test_case_optimization_provider.go @@ -180,11 +180,6 @@ func (t *OptimizationTestCaseProvider) onFuzzerStopping(event FuzzerStoppingEven for _, testCase := range t.testCases { if testCase.status == TestCaseStatusRunning { testCase.status = TestCaseStatusPassed - // Since optimization tests do not really "finish", we will report that they are finished when the fuzzer - // stops. - if event.Fuzzer != nil { - event.Fuzzer.ReportTestCaseFinished(testCase) - } } } return nil diff --git a/fuzzing/test_case_property.go b/fuzzing/test_case_property.go index 9967b1ae..f20d0769 100644 --- a/fuzzing/test_case_property.go +++ b/fuzzing/test_case_property.go @@ -5,6 +5,8 @@ import ( "github.com/crytic/medusa/fuzzing/calls" fuzzerTypes "github.com/crytic/medusa/fuzzing/contracts" "github.com/crytic/medusa/fuzzing/executiontracer" + "github.com/crytic/medusa/logging" + "github.com/crytic/medusa/logging/colors" "github.com/ethereum/go-ethereum/accounts/abi" "strings" ) @@ -39,24 +41,33 @@ func (t *PropertyTestCase) Name() string { return fmt.Sprintf("Property Test: %s.%s", t.targetContract.Name(), t.targetMethod.Sig) } -// Message obtains a text-based printable message which describes the test result. -func (t *PropertyTestCase) Message() string { +// LogMessage obtains a buffer that represents the result of the PropertyTestCase. This buffer can be passed to a logger for +// console or file logging. +func (t *PropertyTestCase) LogMessage() *logging.LogBuffer { // If the test failed, return a failure message. + buffer := logging.NewLogBuffer() if t.Status() == TestCaseStatusFailed { - msg := fmt.Sprintf( - "Property test \"%s.%s\" failed after the following call sequence:\n%s", - t.targetContract.Name(), - t.targetMethod.Sig, - t.CallSequence().String(), - ) + buffer.Append(colors.RedBold, fmt.Sprintf("[%s] ", t.Status()), colors.Bold, t.Name(), colors.Reset, "\n") + buffer.Append(fmt.Sprintf("Test for method \"%s.%s\" failed after the following call sequence:\n", t.targetContract.Name(), t.targetMethod.Sig)) + buffer.Append(colors.Bold, "[Call Sequence]", colors.Reset, "\n") + buffer.Append(t.CallSequence().Log().Elements()...) + // If an execution trace is attached then add it to the message if t.propertyTestTrace != nil { - // TODO: Improve formatting in logging PR - msg += fmt.Sprintf("\nProperty test execution trace:\n%s", t.propertyTestTrace.String()) + buffer.Append(colors.Bold, "[Property Test Execution Trace]", colors.Reset, "\n") + buffer.Append(t.propertyTestTrace.Log().Elements()...) } - return msg + return buffer } - return "" + + buffer.Append(colors.GreenBold, fmt.Sprintf("[%s] ", t.Status()), colors.Bold, t.Name(), colors.Reset) + return buffer +} + +// Message obtains a text-based printable message which describes the result of the PropertyTestCase. +func (t *PropertyTestCase) Message() string { + // Internally, we just call log message and convert it to a string. This can be useful for 3rd party apps + return t.LogMessage().String() } // ID obtains a unique identifier for a test result. diff --git a/fuzzing/valuegeneration/abi_values.go b/fuzzing/valuegeneration/abi_values.go index 5153dee1..56232e9d 100644 --- a/fuzzing/valuegeneration/abi_values.go +++ b/fuzzing/valuegeneration/abi_values.go @@ -3,6 +3,7 @@ package valuegeneration import ( "encoding/hex" "fmt" + "github.com/crytic/medusa/logging" "math/big" "reflect" "strconv" @@ -93,7 +94,10 @@ func GenerateAbiValue(generator ValueGenerator, inputType *abi.Type) any { // - Mappings cannot be used in public/external methods and must reference storage, so we shouldn't ever // see cases of it unless Solidity was updated in the future. // - FixedPoint types are currently unsupported. - panic(fmt.Sprintf("attempt to generate function argument of unsupported type: '%s'", inputType.String())) + + err := fmt.Errorf("attempt to generate function argument of unsupported type: '%s'", inputType.String()) + logging.GlobalLogger.Panic("Failed to generate abi value", err) + return nil } } diff --git a/go.mod b/go.mod index 3e2af559..ca1b0639 100644 --- a/go.mod +++ b/go.mod @@ -8,6 +8,7 @@ require ( github.com/fxamacker/cbor v1.5.1 github.com/google/uuid v1.3.0 github.com/pkg/errors v0.9.1 + github.com/rs/zerolog v1.29.0 github.com/spf13/cobra v1.7.0 github.com/spf13/pflag v1.0.5 github.com/stretchr/testify v1.8.4 @@ -43,6 +44,8 @@ require ( github.com/klauspost/compress v1.15.15 // indirect github.com/kr/pretty v0.3.1 // indirect github.com/kr/text v0.2.0 // indirect + github.com/mattn/go-colorable v0.1.13 // indirect + github.com/mattn/go-isatty v0.0.16 // indirect github.com/mattn/go-runewidth v0.0.14 // indirect github.com/matttproud/golang_protobuf_extensions v1.0.4 // indirect github.com/olekukonko/tablewriter v0.0.5 // indirect diff --git a/go.sum b/go.sum index 7e235f86..fe8142b2 100644 --- a/go.sum +++ b/go.sum @@ -48,6 +48,7 @@ github.com/codegangsta/inject v0.0.0-20150114235600-33e0aa1cb7c0/go.mod h1:4Zcju github.com/coreos/etcd v3.3.10+incompatible/go.mod h1:uF7uidLiAD3TWHmW31ZFd/JWoc32PjwdhPthX9715RE= github.com/coreos/go-etcd v2.0.0+incompatible/go.mod h1:Jez6KQU2B/sWsbdaef3ED8NzMklzPG4d5KIOhIy30Tk= github.com/coreos/go-semver v0.2.0/go.mod h1:nnelYz7RCh+5ahJtPPxZlU+153eP4D4r3EedlOD2RNk= +github.com/coreos/go-systemd/v22 v22.3.3-0.20220203105225-a9a7ef127534/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc= github.com/cpuguy83/go-md2man v1.0.10/go.mod h1:SmD6nW6nTyfqj6ABTjUi3V3JVMnlJmwcJI5acqYI6dE= github.com/cpuguy83/go-md2man/v2 v2.0.2/go.mod h1:tgQtvFlXSQOSOSIRvRPT7W67SCa46tRHOmNcaadrF8o= github.com/creack/pty v1.1.9/go.mod h1:oKZEueFk5CKHvIhNR5MUki03XCEU+Q6VDXinZuGJ33E= @@ -101,6 +102,7 @@ github.com/go-stack/stack v1.8.1/go.mod h1:dcoOX6HbPZSZptuspn9bctJ+N/CnF5gGygcUP github.com/gobwas/httphead v0.0.0-20180130184737-2c6c146eadee/go.mod h1:L0fX3K22YWvt/FAX9NnzrNzcI4wNYi9Yku4O0LKYflo= github.com/gobwas/pool v0.2.0/go.mod h1:q8bcK0KcYlCgd9e7WYLm9LpyS+YeLd8JVDW6WezmKEw= github.com/gobwas/ws v1.0.2/go.mod h1:szmBTxLgaFppYjEmNtny/v3w89xOydFnnZMcgRRu/EM= +github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA= github.com/gogo/googleapis v0.0.0-20180223154316-0cd9801be74a/go.mod h1:gf4bu3Q80BeJ6H1S1vYPm8/ELATdvryBaNFGgqEef3s= github.com/gogo/googleapis v1.4.1/go.mod h1:2lpHqI5OcWCtVElxXnPt+s8oJvMpySlOyM6xDCrzib4= github.com/gogo/protobuf v1.1.1/go.mod h1:r8qH/GZQm5c6nD/R0oafs1akxWv10x8SbQlK7atdtwQ= @@ -197,11 +199,16 @@ github.com/magiconair/properties v1.8.0/go.mod h1:PppfXfuXeibc/6YijjN8zIbojt8czP github.com/mattn/go-colorable v0.1.2/go.mod h1:U0ppj6V5qS13XJ6of8GYAs25YV2eR4EVcfRqFIhoBtE= github.com/mattn/go-colorable v0.1.8/go.mod h1:u6P/XSegPjTcexA+o6vUJrdnUu04hMope9wVRipJSqc= github.com/mattn/go-colorable v0.1.11/go.mod h1:u5H1YNBxpqRaxsYJYSkiCWKzEfiAb1Gb520KVy5xxl4= +github.com/mattn/go-colorable v0.1.12/go.mod h1:u5H1YNBxpqRaxsYJYSkiCWKzEfiAb1Gb520KVy5xxl4= +github.com/mattn/go-colorable v0.1.13 h1:fFA4WZxdEF4tXPZVKMLwD8oUnCTTo08duU7wxecdEvA= +github.com/mattn/go-colorable v0.1.13/go.mod h1:7S9/ev0klgBDR4GtXTXX8a3vIGJpMovkB8vQcUbaXHg= github.com/mattn/go-isatty v0.0.7/go.mod h1:Iq45c/XA43vh69/j3iqttzPXn0bhXyGjM0Hdxcsrc5s= github.com/mattn/go-isatty v0.0.8/go.mod h1:Iq45c/XA43vh69/j3iqttzPXn0bhXyGjM0Hdxcsrc5s= github.com/mattn/go-isatty v0.0.9/go.mod h1:YNRxwqDuOph6SZLI9vUUz6OYw3QyUt7WiY2yME+cCiQ= github.com/mattn/go-isatty v0.0.12/go.mod h1:cbi8OIDigv2wuxKPP5vlRcQ1OAZbq2CE4Kysco4FUpU= github.com/mattn/go-isatty v0.0.14/go.mod h1:7GGIvUiUoEMVVmxf/4nioHXj79iQHKdU27kJ6hsGG94= +github.com/mattn/go-isatty v0.0.16 h1:bq3VjFmv/sOjHtdEhmkEV4x1AJtvUvOJ2PFAZ5+peKQ= +github.com/mattn/go-isatty v0.0.16/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM= github.com/mattn/go-runewidth v0.0.9/go.mod h1:H031xJmbD/WCDINGzjvQ9THkh0rPKHF+m2gUSrubnMI= github.com/mattn/go-runewidth v0.0.14 h1:+xnbZSEeDbOIg5/mE6JF0w6n9duR1l3/WmbinWVwUuU= github.com/mattn/go-runewidth v0.0.14/go.mod h1:Jdepj2loyihRzMpdS35Xk/zdY8IAYHsh153qUoGf23w= @@ -271,6 +278,9 @@ github.com/rogpeppe/go-internal v1.6.1/go.mod h1:xXDCJY+GAPziupqXw64V24skbSoqbTE github.com/rogpeppe/go-internal v1.8.1/go.mod h1:JeRgkft04UBgHMgCIwADu4Pn6Mtm5d4nPKWu0nJ5d+o= github.com/rogpeppe/go-internal v1.9.0 h1:73kH8U+JUqXU8lRuOHeVHaa/SZPifC7BkcraZVejAe8= github.com/rogpeppe/go-internal v1.9.0/go.mod h1:WtVeX8xhTBvf0smdhujwtBcq4Qrzq/fJaraNFVN+nFs= +github.com/rs/xid v1.4.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg= +github.com/rs/zerolog v1.29.0 h1:Zes4hju04hjbvkVkOhdl2HpZa+0PmVwigmo8XoORE5w= +github.com/rs/zerolog v1.29.0/go.mod h1:NILgTygv/Uej1ra5XxGf82ZFSLk58MFGAUS2o6usyD0= github.com/russross/blackfriday v1.5.2/go.mod h1:JO/DiYxRf+HjHt06OyowR9PTA263kcR/rfWxYHBV53g= github.com/russross/blackfriday/v2 v2.1.0/go.mod h1:+Rmxgy9KzJVeS9/2gXHxylqXiyQDYRxCVz55jmeOWTM= github.com/ryanuber/columnize v2.1.0+incompatible/go.mod h1:sm1tb6uqfes/u+d4ooFouqFdy9/2g9QGwK3SQygK0Ts= @@ -418,6 +428,7 @@ golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6/go.mod h1:oPkhp1MJrh7nUepCBc golang.org/x/sys v0.0.0-20211007075335-d3039528d8ac/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20220209214540-3681064d5158/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20220405052023-b1e9470b6e64/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.2.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.10.0 h1:SqMFp9UcQJZa+pmYuAKjd9xq1f0j5rLcDIk0mj4qAsA= golang.org/x/sys v0.10.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= diff --git a/logging/colors/color_funcs.go b/logging/colors/color_funcs.go new file mode 100644 index 00000000..4a201dbb --- /dev/null +++ b/logging/colors/color_funcs.go @@ -0,0 +1,107 @@ +package colors + +import "fmt" + +// ColorFunc is an alias type for a coloring function that accepts anything and returns a colorized string +type ColorFunc = func(s any) string + +// Reset is a ColorFunc that simply returns the input as a string. It is basically a no-op and is used for resetting the +// color context during complex logging operations. +func Reset(s any) string { + return fmt.Sprintf("%v", s) +} + +// Black is a ColorFunc that returns a black-colorized string of the provided input +func Black(s any) string { + return Colorize(s, BLACK) +} + +// BlackBold is a ColorFunc that returns a black-bold-colorized string of the provided input +func BlackBold(s any) string { + return Colorize(Colorize(s, BLACK), BOLD) +} + +// Red is a ColorFunc that returns a red-colorized string of the provided input +func Red(s any) string { + return Colorize(s, RED) +} + +// RedBold is a ColorFunc that returns a red-bold-colorized string of the provided input +func RedBold(s any) string { + return Colorize(Colorize(s, RED), BOLD) +} + +// Green is a ColorFunc that returns a green-colorized string of the provided input +func Green(s any) string { + return Colorize(s, GREEN) +} + +// GreenBold is a ColorFunc that returns a green-bold-colorized string of the provided input +func GreenBold(s any) string { + return Colorize(Colorize(s, GREEN), BOLD) +} + +// Yellow is a ColorFunc that returns a yellow-colorized string of the provided input +func Yellow(s any) string { + return Colorize(s, YELLOW) +} + +// YellowBold is a ColorFunc that returns a yellow-bold-colorized string of the provided input +func YellowBold(s any) string { + return Colorize(Colorize(s, YELLOW), BOLD) +} + +// Blue is a ColorFunc that returns a blue-colorized string of the provided input +func Blue(s any) string { + return Colorize(s, BLUE) +} + +// BlueBold is a ColorFunc that returns a blue-bold-colorized string of the provided input +func BlueBold(s any) string { + return Colorize(Colorize(s, BLUE), BOLD) +} + +// Magenta is a ColorFunc that returns a magenta-colorized string of the provided input +func Magenta(s any) string { + return Colorize(s, MAGENTA) +} + +// MagentaBold is a ColorFunc that returns a magenta-bold-colorized string of the provided input +func MagentaBold(s any) string { + return Colorize(Colorize(s, MAGENTA), BOLD) +} + +// Cyan is a ColorFunc that returns a cyan-colorized string of the provided input +func Cyan(s any) string { + return Colorize(s, CYAN) +} + +// CyanBold is a ColorFunc that returns a cyan-bold-colorized string of the provided input +func CyanBold(s any) string { + return Colorize(Colorize(s, CYAN), BOLD) +} + +// White is a ColorFunc that returns a white-colorized string of the provided input +func White(s any) string { + return Colorize(s, WHITE) +} + +// WhiteBold is a ColorFunc that returns a white-bold-colorized string of the provided input +func WhiteBold(s any) string { + return Colorize(Colorize(s, WHITE), BOLD) +} + +// Bold is a ColorFunc that returns a bolded string of the provided input +func Bold(s any) string { + return Colorize(s, BOLD) +} + +// DarkGray is a ColorFunc that returns a dark-gray-colorized string of the provided input +func DarkGray(s any) string { + return Colorize(s, DARK_GRAY) +} + +// DarkGrayBold is a ColorFunc that returns a dark-gray-bold-colorized string of the provided input +func DarkGrayBold(s any) string { + return Colorize(Colorize(s, DARK_GRAY), BOLD) +} diff --git a/logging/colors/colorize_unix.go b/logging/colors/colorize_unix.go new file mode 100644 index 00000000..89ea510d --- /dev/null +++ b/logging/colors/colorize_unix.go @@ -0,0 +1,15 @@ +//go:build !windows +// +build !windows + +package colors + +import "fmt" + +// EnableColor is a no-op function for non-windows systems because we know that they support ANSI escape codes +func EnableColor() {} + +// Colorize returns the string s wrapped in ANSI code c for non-windows systems +// Source: https://github.com/rs/zerolog/blob/4fff5db29c3403bc26dee9895e12a108aacc0203/console.go +func Colorize(s any, c Color) string { + return fmt.Sprintf("\x1b[%dm%v\x1b[0m", c, s) +} diff --git a/logging/colors/colorize_windows.go b/logging/colors/colorize_windows.go new file mode 100644 index 00000000..87266688 --- /dev/null +++ b/logging/colors/colorize_windows.go @@ -0,0 +1,66 @@ +//go:build windows +// +build windows + +package colors + +import ( + "fmt" + "golang.org/x/sys/windows" + "os" +) + +var enabled bool + +// EnableColor will make a kernel call to enable ANSI escape codes on both stdout and stderr. Note that if enablement +// on either stream fails, then coloring will not be enabled. +func EnableColor() { + var mode uint32 + fds := []uintptr{os.Stdout.Fd(), os.Stderr.Fd()} + + // Iterate across each file descriptor and enable coloring + for _, fd := range fds { + // Obtain our current console mode. + consoleHandle := windows.Handle(fd) + err := windows.GetConsoleMode(consoleHandle, &mode) + if err != nil { + enabled = false + return + } + + // If color is not enabled, try to enable it. + if mode&windows.ENABLE_VIRTUAL_TERMINAL_PROCESSING == 0 { + err = windows.SetConsoleMode(consoleHandle, mode|windows.ENABLE_VIRTUAL_TERMINAL_PROCESSING) + if err != nil { + enabled = false + return + } + } + + // Fetch the console mode once more + err = windows.GetConsoleMode(consoleHandle, &mode) + if err != nil { + enabled = false + return + } + + // Set our enabled status after trying to enable it. + enabled = mode&windows.ENABLE_VIRTUAL_TERMINAL_PROCESSING != 0 + + // If we failed to enable on this file descriptor, exit out + if !enabled { + return + } + } +} + +// Colorize returns the string s wrapped in ANSI code c assuming that ANSI is supported on the Windows version +// Source: https://github.com/rs/zerolog/blob/4fff5db29c3403bc26dee9895e12a108aacc0203/console.go +func Colorize(s any, c Color) string { + // If ANSI is not supported then just return the original string + if !enabled { + return fmt.Sprintf("%v", s) + } + + // Otherwise, returned an ANSI-wrapped string + return fmt.Sprintf("\x1b[%dm%v\x1b[0m", c, s) +} diff --git a/logging/colors/constants.go b/logging/colors/constants.go new file mode 100644 index 00000000..c1a7657a --- /dev/null +++ b/logging/colors/constants.go @@ -0,0 +1,34 @@ +package colors + +type Color int + +// This is taken from zerolog's repo and will be used to colorize log output +// Source: https://github.com/rs/zerolog/blob/4fff5db29c3403bc26dee9895e12a108aacc0203/console.go +const ( + // BLACK is the ANSI code for black + BLACK Color = iota + 30 + // COLOR_RED is the ANSI code for red + RED + // GREEN is the ANSI code for green + GREEN + // YELLOW is the ANSI code for yellow + YELLOW + // BLUE is the ANSI code for blue + BLUE + // MAGENTA is the ANSI code for magenta + MAGENTA + // CYAN is the ANSI code for cyan + CYAN + // WHITE is the ANSI code for white + WHITE + // BOLD is the ANSI code for bold tet + BOLD = 1 + // DARK_GRAY is the ANSI code for dark gray + DARK_GRAY = 90 +) + +// This enum is to identify special unicode characters that will be used for pretty console output +const ( + // LEFT_ARROW is the unicode string for a left arrow glyph + LEFT_ARROW = "\u21fe" +) diff --git a/logging/colors/init.go b/logging/colors/init.go new file mode 100644 index 00000000..758c7d4f --- /dev/null +++ b/logging/colors/init.go @@ -0,0 +1,7 @@ +package colors + +// init will ensure that ANSI coloring is enabled on Windows and Unix systems. Note that ANSI coloring is enabled by +// default on Unix system and Windows needs specific kernel calls for enablement +func init() { + EnableColor() +} diff --git a/logging/log_buffer.go b/logging/log_buffer.go new file mode 100644 index 00000000..70abf4a4 --- /dev/null +++ b/logging/log_buffer.go @@ -0,0 +1,33 @@ +package logging + +// LogBuffer is a helper object that can be used to buffer log messages. A log buffer is effectively a list of arguments +// of any type. This object is especially useful when attempting to log complex objects (e.g. execution trace) that have +// complex coloring schemes and formatting. The LogBuffer can then be passed on to a Logger object to then log the buffer +// to console and any other writers (e.g. file). +type LogBuffer struct { + // elements describes the list of elements that eventually need to be concatenated together in the Logger + elements []any +} + +// NewLogBuffer creates a new LogBuffer object +func NewLogBuffer() *LogBuffer { + return &LogBuffer{ + elements: make([]any, 0), + } +} + +// Append appends a variadic set of elements to the list of elements +func (l *LogBuffer) Append(newElements ...any) { + l.elements = append(l.elements, newElements...) +} + +// Elements returns the list of elements stored in this LogBuffer +func (l *LogBuffer) Elements() []any { + return l.elements +} + +// String provides the non-colorized string representation of the LogBuffer +func (l LogBuffer) String() string { + _, msg, _, _ := buildMsgs(l.elements) + return msg +} diff --git a/logging/logger.go b/logging/logger.go new file mode 100644 index 00000000..6385d182 --- /dev/null +++ b/logging/logger.go @@ -0,0 +1,347 @@ +package logging + +import ( + "fmt" + "github.com/crytic/medusa/logging/colors" + "github.com/rs/zerolog" + "io" + "os" + "strings" +) + +// GlobalLogger describes a Logger that is disabled by default and is instantiated when the fuzzer is created. Each module/package +// should create its own sub-logger. This allows to create unique logging instances depending on the use case. +var GlobalLogger = NewLogger(zerolog.Disabled, false, nil) + +// Logger describes a custom logging object that can log events to any arbitrary channel and can handle specialized +// output to console as well +type Logger struct { + // level describes the log level + level zerolog.Level + + // multiLogger describes a logger that will be used to output logs to any arbitrary channel(s) in either structured + // or unstructured format. + multiLogger zerolog.Logger + + // consoleLogger describes a logger that will be used to output unstructured output to console. + // We are creating a separate logger for console so that we can support specialized formatting / custom coloring. + consoleLogger zerolog.Logger + + // writers describes a list of io.Writer objects where log output will go. This writers list can be appended to / + // removed from. + writers []io.Writer +} + +// LogFormat describes what format to log in +type LogFormat string + +const ( + // STRUCTURED describes that logging should be done in structured JSON format + STRUCTURED LogFormat = "structured" + // UNSTRUCTRED describes that logging should be done in an unstructured format + UNSTRUCTURED LogFormat = "unstructured" +) + +// StructuredLogInfo describes a key-value mapping that can be used to log structured data +type StructuredLogInfo map[string]any + +// NewLogger will create a new Logger object with a specific log level. The Logger can output to console, if enabled, +// and output logs to any number of arbitrary io.Writer channels +func NewLogger(level zerolog.Level, consoleEnabled bool, writers ...io.Writer) *Logger { + // The two base loggers are effectively loggers that are disabled + // We are creating instances of them so that we do not get nil pointer dereferences down the line + baseMultiLogger := zerolog.New(os.Stdout).Level(zerolog.Disabled) + baseConsoleLogger := zerolog.New(os.Stdout).Level(zerolog.Disabled) + + // If we are provided a list of writers, update the multi logger + if len(writers) > 0 { + baseMultiLogger = zerolog.New(zerolog.MultiLevelWriter(writers...)).Level(level).With().Timestamp().Logger() + } + + // If console logging is enabled, update the console logger + if consoleEnabled { + consoleWriter := setupDefaultFormatting(zerolog.ConsoleWriter{Out: os.Stdout}, level) + baseConsoleLogger = zerolog.New(consoleWriter).Level(level) + } + + return &Logger{ + level: level, + multiLogger: baseMultiLogger, + consoleLogger: baseConsoleLogger, + writers: writers, + } +} + +// NewSubLogger will create a new Logger with unique context in the form of a key-value pair. The expected use of this +// function is for each package to have their own unique logger so that parsing of logs is "grep-able" based on some key +func (l *Logger) NewSubLogger(key string, value string) *Logger { + subFileLogger := l.multiLogger.With().Str(key, value).Logger() + subConsoleLonger := l.consoleLogger.With().Str(key, value).Logger() + return &Logger{ + level: l.level, + multiLogger: subFileLogger, + consoleLogger: subConsoleLonger, + writers: l.writers, + } +} + +// AddWriter will add a writer to the list of channels where log output will be sent. +func (l *Logger) AddWriter(writer io.Writer, format LogFormat) { + // Check to see if the writer is already in the array of writers + for _, w := range l.writers { + if writer == w { + return + } + } + + // If we want unstructured output, wrap the base writer object into a console writer so that we get unstructured output with no ANSI coloring + if format == UNSTRUCTURED { + writer = zerolog.ConsoleWriter{Out: writer, NoColor: true} + } + + // Add it to the list of writers and update the multi logger + l.writers = append(l.writers, writer) + l.multiLogger = zerolog.New(zerolog.MultiLevelWriter(l.writers...)).Level(l.level).With().Timestamp().Logger() +} + +// RemoveWriter will remove a writer from the list of writers that the logger manages. If the writer does not exist, this +// function is a no-op +func (l *Logger) RemoveWriter(writer io.Writer) { + // Iterate through the writers + for i, w := range l.writers { + if writer == w { + // Create a new slice without the writer at index i + l.writers = append(l.writers[:i], l.writers[i+1]) + } + } +} + +// Level will get the log level of the Logger +func (l *Logger) Level() zerolog.Level { + return l.level +} + +// SetLevel will update the log level of the Logger +func (l *Logger) SetLevel(level zerolog.Level) { + l.level = level + l.multiLogger = l.multiLogger.Level(level) + l.consoleLogger = l.consoleLogger.Level(level) +} + +// Trace is a wrapper function that will log a trace event +func (l *Logger) Trace(args ...any) { + // Build the messages and retrieve any error or associated structured log info + consoleMsg, multiMsg, err, info := buildMsgs(args...) + + // Instantiate log events + consoleLog := l.consoleLogger.Trace() + multiLog := l.multiLogger.Trace() + + // Chain the error + chainError(consoleLog, multiLog, err, l.level <= zerolog.DebugLevel) + + // Chain the structured log info and messages and send off the logs + chainStructuredLogInfoAndMsgs(consoleLog, multiLog, info, consoleMsg, multiMsg) +} + +// Debug is a wrapper function that will log a debug event +func (l *Logger) Debug(args ...any) { + // Build the messages and retrieve any error or associated structured log info + consoleMsg, multiMsg, err, info := buildMsgs(args...) + + // Instantiate log events + consoleLog := l.consoleLogger.Debug() + multiLog := l.multiLogger.Debug() + + // Chain the error + chainError(consoleLog, multiLog, err, l.level <= zerolog.DebugLevel) + + // Chain the structured log info and messages and send off the logs + chainStructuredLogInfoAndMsgs(consoleLog, multiLog, info, consoleMsg, multiMsg) +} + +// Info is a wrapper function that will log an info event +func (l *Logger) Info(args ...any) { + // Build the messages and retrieve any error or associated structured log info + consoleMsg, multiMsg, err, info := buildMsgs(args...) + + // Instantiate log events + consoleLog := l.consoleLogger.Info() + multiLog := l.multiLogger.Info() + + // Chain the error + chainError(consoleLog, multiLog, err, l.level <= zerolog.DebugLevel) + + // Chain the structured log info and messages and send off the logs + chainStructuredLogInfoAndMsgs(consoleLog, multiLog, info, consoleMsg, multiMsg) +} + +// Warn is a wrapper function that will log a warning event both on console +func (l *Logger) Warn(args ...any) { + // Build the messages and retrieve any error or associated structured log info + consoleMsg, multiMsg, err, info := buildMsgs(args...) + + // Instantiate log events + consoleLog := l.consoleLogger.Warn() + multiLog := l.multiLogger.Warn() + + // Chain the error + chainError(consoleLog, multiLog, err, l.level <= zerolog.DebugLevel) + + // Chain the structured log info and messages and send off the logs + chainStructuredLogInfoAndMsgs(consoleLog, multiLog, info, consoleMsg, multiMsg) +} + +// Error is a wrapper function that will log an error event. +func (l *Logger) Error(args ...any) { + // Build the messages and retrieve any error or associated structured log info + consoleMsg, multiMsg, err, info := buildMsgs(args...) + + // Instantiate log events + consoleLog := l.consoleLogger.Error() + multiLog := l.multiLogger.Error() + + // Chain the error + chainError(consoleLog, multiLog, err, l.level <= zerolog.DebugLevel) + + // Chain the structured log info and messages and send off the logs + chainStructuredLogInfoAndMsgs(consoleLog, multiLog, info, consoleMsg, multiMsg) +} + +// Panic is a wrapper function that will log a panic event +func (l *Logger) Panic(args ...any) { + // Build the messages and retrieve any error or associated structured log info + consoleMsg, multiMsg, err, info := buildMsgs(args...) + + // Instantiate log events + consoleLog := l.consoleLogger.Panic() + multiLog := l.multiLogger.Panic() + + // Chain the error + chainError(consoleLog, multiLog, err, true) + + // Chain the structured log info and messages and send off the logs + chainStructuredLogInfoAndMsgs(consoleLog, multiLog, info, consoleMsg, multiMsg) +} + +// buildMsgs describes a function that takes in a variadic list of arguments of any type and returns two strings and, +// optionally, an error and a StructuredLogInfo object. The first string will be a colorized-string that can be used for +// console logging while the second string will be a non-colorized one that can be used for file/structured logging. +// The error and the StructuredLogInfo can be used to add additional context to log messages +func buildMsgs(args ...any) (string, string, error, StructuredLogInfo) { + // Guard clause + if len(args) == 0 { + return "", "", nil, nil + } + + // Initialize the base color context, the string buffers and the structured log info object + colorCtx := colors.Reset + consoleOutput := make([]string, 0) + fileOutput := make([]string, 0) + var info StructuredLogInfo + var err error + + // Iterate through each argument in the list and switch on type + for _, arg := range args { + switch t := arg.(type) { + case colors.ColorFunc: + // If the argument is a color function, switch the current color context + colorCtx = t + case StructuredLogInfo: + // Note that only one structured log info can be provided for each log message + info = t + case error: + // Note that only one error can be provided for each log message + err = t + default: + // In the base case, append the object to the two string buffers. The console string buffer will have the + // current color context applied to it. + consoleOutput = append(consoleOutput, colorCtx(t)) + fileOutput = append(fileOutput, fmt.Sprintf("%v", t)) + } + } + + return strings.Join(consoleOutput, ""), strings.Join(fileOutput, ""), err, info +} + +// chainError is a helper function that takes in a *zerolog.Event for console and multi-log output and chains an error +// to both events. If debug is true, then a stack trace is added to both events as well. +func chainError(consoleLog *zerolog.Event, multiLog *zerolog.Event, err error, debug bool) { + // First append the errors to each event. Note that even if err is nil, there will not be a panic here + consoleLog.Err(err) + multiLog.Err(err) + + // If we are in debug mode or below, then we will add the stack traces as well for debugging + if debug { + consoleLog.Stack() + multiLog.Stack() + } +} + +// chainStructuredLogInfoAndMsgs is a helper function that takes in a *zerolog.Event for console and multi-log output, +// chains any StructuredLogInfo provided to it, adds the associated messages, and sends out the logs to their respective +// channels. +func chainStructuredLogInfoAndMsgs(consoleLog *zerolog.Event, multiLog *zerolog.Event, info StructuredLogInfo, consoleMsg string, multiMsg string) { + // If we are provided a structured log info object, add that as a key-value pair to the events + if info != nil { + consoleLog.Any("info", info) + multiLog.Any("info", info) + } + + // Append the messages to each event. This will also result in the log events being sent out to their respective + // streams. Note that we are deferring the msg to multi logger in case we are logging a panic and want to make sure that + // all channels receive the panic log + defer multiLog.Msg(multiMsg) + consoleLog.Msg(consoleMsg) +} + +// setupDefaultFormatting will update the console logger's formatting to the medusa standard +func setupDefaultFormatting(writer zerolog.ConsoleWriter, level zerolog.Level) zerolog.ConsoleWriter { + // Get rid of the timestamp for console output + writer.FormatTimestamp = func(i interface{}) string { + return "" + } + + // We will define a custom format for each level + writer.FormatLevel = func(i any) string { + // Create a level object for better switch logic + level, err := zerolog.ParseLevel(i.(string)) + if err != nil { + panic(fmt.Sprintf("unable to parse the log level: %v", err)) + } + + // Switch on the level and return a custom, colored string + switch level { + case zerolog.TraceLevel: + // Return a bold, cyan "trace" string + return colors.CyanBold(zerolog.LevelTraceValue) + case zerolog.DebugLevel: + // Return a bold, blue "debug" string + return colors.BlueBold(zerolog.LevelDebugValue) + case zerolog.InfoLevel: + // Return a bold, green left arrow + return colors.GreenBold(colors.LEFT_ARROW) + case zerolog.WarnLevel: + // Return a bold, yellow "warn" string + return colors.YellowBold(zerolog.LevelWarnValue) + case zerolog.ErrorLevel: + // Return a bold, red "err" string + return colors.RedBold(zerolog.LevelErrorValue) + case zerolog.FatalLevel: + // Return a bold, red "fatal" string + return colors.RedBold(zerolog.LevelFatalValue) + case zerolog.PanicLevel: + // Return a bold, red "panic" string + return colors.RedBold(zerolog.LevelPanicValue) + default: + return i.(string) + } + } + + // If we are above debug level, we want to get rid of the `module` component when logging to console + if level > zerolog.DebugLevel { + writer.FieldsExclude = []string{"module"} + } + + return writer +} diff --git a/main.go b/main.go index 2c8c7295..4902eaeb 100644 --- a/main.go +++ b/main.go @@ -1,7 +1,6 @@ package main import ( - "fmt" "github.com/crytic/medusa/cmd" "os" ) @@ -10,10 +9,7 @@ func main() { // Run our root CLI command, which contains all underlying command logic and will handle parsing/invocation. err := cmd.Execute() - // Print any error we encountered if err != nil { - // TODO: Replace this when we have an appropriate logger in place. - fmt.Printf("ERROR:\n%s", err.Error()) os.Exit(1) } } diff --git a/utils/fs_utils.go b/utils/fs_utils.go index f515b243..df656bc6 100644 --- a/utils/fs_utils.go +++ b/utils/fs_utils.go @@ -2,11 +2,38 @@ package utils import ( "fmt" + "github.com/pkg/errors" "io" "os" "path/filepath" ) +// CreateFile will create a file at the given path and file name combination. If the path is the empty string, the +// file will be created in the current working directory +func CreateFile(path string, fileName string) (*os.File, error) { + // By default, the path will be the name of the file + filePath := fileName + + // Check to see if the file needs to be created in another directory or the working directory + if path != "" { + // Make the directory, if it does not exist already + err := MakeDirectory(path) + if err != nil { + return nil, err + } + // Since the path is non-empty, concatenate the path with the name of the file + filePath = filepath.Join(path, fileName) + } + + // Create the file + file, err := os.Create(filePath) + if err != nil { + return nil, errors.WithStack(err) + } + + return file, nil +} + // CopyFile copies a file from a source path to a destination path. File permissions are retained. Returns an error // if one occurs. func CopyFile(sourcePath string, targetPath string) error { diff --git a/utils/randomutils/fork_random.go b/utils/randomutils/fork_random.go index 071da2d3..192b68d6 100644 --- a/utils/randomutils/fork_random.go +++ b/utils/randomutils/fork_random.go @@ -2,6 +2,7 @@ package randomutils import ( "encoding/binary" + "github.com/crytic/medusa/logging" "math/rand" ) @@ -13,7 +14,7 @@ func ForkRandomProvider(randomProvider *rand.Rand) *rand.Rand { b := make([]byte, 8) _, err := randomProvider.Read(b) if err != nil { - panic(err) + logging.GlobalLogger.Panic("Failed to fork random child provider", err) } // Return a new random provider with our derived seed. diff --git a/utils/reflectionutils/reflected_type_utils.go b/utils/reflectionutils/reflected_type_utils.go index a3ffd48e..34e277b5 100644 --- a/utils/reflectionutils/reflected_type_utils.go +++ b/utils/reflectionutils/reflected_type_utils.go @@ -2,6 +2,7 @@ package reflectionutils import ( "fmt" + "github.com/crytic/medusa/logging" "reflect" ) @@ -54,7 +55,9 @@ func CopyReflectedType(reflectedValue reflect.Value) reflect.Value { } return newStruct } - panic("failed to copy reflected value, type not supported") + + logging.GlobalLogger.Panic("Failed to copy reflected value", fmt.Errorf("type not supported")) + return reflectedValue } // GetReflectedArrayValues obtains the values of each element of a reflected array or slice variable. @@ -71,7 +74,9 @@ func GetReflectedArrayValues(reflectedArray reflect.Value) []any { } return values } - panic("failed to get reflected array values, type not supported") + + logging.GlobalLogger.Panic("Failed to get reflected array values", fmt.Errorf("type not supported")) + return nil } // SetReflectedArrayValues takes an array or slice of the same length as the values provided, and sets each element @@ -93,5 +98,7 @@ func SetReflectedArrayValues(reflectedArray reflect.Value, values []any) error { } return nil } - panic("failed to set reflected array values, type not supported") + + logging.GlobalLogger.Panic("Failed to set reflected array values", fmt.Errorf("type not supported")) + return nil }