log_listener.go

Documentation: github.com/tetratelabs/wazero/experimental/logging

     1  package logging
     2  
     3  import (
     4  	"bufio"
     5  	"context"
     6  	"io"
     7  
     8  	"github.com/tetratelabs/wazero/api"
     9  	"github.com/tetratelabs/wazero/experimental"
    10  	aslogging "github.com/tetratelabs/wazero/internal/assemblyscript/logging"
    11  	gologging "github.com/tetratelabs/wazero/internal/gojs/logging"
    12  	"github.com/tetratelabs/wazero/internal/logging"
    13  	"github.com/tetratelabs/wazero/internal/wasip1"
    14  	wasilogging "github.com/tetratelabs/wazero/internal/wasip1/logging"
    15  )
    16  
    17  type Writer interface {
    18  	io.Writer
    19  	io.StringWriter
    20  }
    21  
    22  // LogScopes is a bit flag of host function groups to log. e.g. LogScopeRandom.
    23  //
    24  // To specify all scopes, use LogScopeAll. For multiple scopes, OR them
    25  // together like this:
    26  //
    27  //	scope = logging.LogScopeRandom | logging.LogScopeFilesystem
    28  //
    29  // Note: Numeric values are not intended to be interpreted except as bit flags.
    30  type LogScopes = logging.LogScopes
    31  
    32  const (
    33  	// LogScopeNone means nothing should be logged
    34  	LogScopeNone = logging.LogScopeNone
    35  	// LogScopeClock enables logging for functions such as `clock_time_get`.
    36  	LogScopeClock = logging.LogScopeClock
    37  	// LogScopeProc enables logging for functions such as `proc_exit`.
    38  	//
    39  	// Note: This includes functions that both log and exit. e.g. `abort`.
    40  	LogScopeProc = logging.LogScopeProc
    41  	// LogScopeFilesystem enables logging for functions such as `path_open`.
    42  	//
    43  	// Note: This doesn't log writes to the console.
    44  	LogScopeFilesystem = logging.LogScopeFilesystem
    45  	// LogScopeMemory enables logging for functions such as
    46  	// `emscripten_notify_memory_growth`.
    47  	LogScopeMemory = logging.LogScopeMemory
    48  	// LogScopePoll enables logging for functions such as `poll_oneoff`.
    49  	LogScopePoll = logging.LogScopePoll
    50  	// LogScopeRandom enables logging for functions such as `random_get`.
    51  	LogScopeRandom = logging.LogScopeRandom
    52  	// LogScopeSock enables logging for functions such as `sock_accept`.
    53  	LogScopeSock = logging.LogScopeSock
    54  	// LogScopeAll means all functions should be logged.
    55  	LogScopeAll = logging.LogScopeAll
    56  )
    57  
    58  // NewLoggingListenerFactory is an experimental.FunctionListenerFactory that
    59  // logs all functions that have a name to the writer.
    60  //
    61  // Use NewHostLoggingListenerFactory if only interested in host interactions.
    62  func NewLoggingListenerFactory(w Writer) experimental.FunctionListenerFactory {
    63  	return &loggingListenerFactory{w: toInternalWriter(w), scopes: LogScopeAll}
    64  }
    65  
    66  // NewHostLoggingListenerFactory is an experimental.FunctionListenerFactory
    67  // that logs exported and host functions to the writer.
    68  //
    69  // This is an alternative to NewLoggingListenerFactory, and would weed out
    70  // guest defined functions such as those implementing garbage collection.
    71  //
    72  // For example, "_start" is defined by the guest, but exported, so would be
    73  // written to the w in order to provide minimal context needed to
    74  // understand host calls such as "args_get".
    75  //
    76  // The scopes parameter can be set to LogScopeAll or constrained.
    77  func NewHostLoggingListenerFactory(w Writer, scopes logging.LogScopes) experimental.FunctionListenerFactory {
    78  	return &loggingListenerFactory{w: toInternalWriter(w), hostOnly: true, scopes: scopes}
    79  }
    80  
    81  func toInternalWriter(w Writer) logging.Writer {
    82  	if w, ok := w.(logging.Writer); ok {
    83  		return w
    84  	}
    85  	return bufio.NewWriter(w)
    86  }
    87  
    88  type loggingListenerFactory struct {
    89  	w        logging.Writer
    90  	hostOnly bool
    91  	scopes   logging.LogScopes
    92  	stack    logStack
    93  }
    94  
    95  type flusher interface {
    96  	Flush() error
    97  }
    98  
    99  // NewFunctionListener implements the same method as documented on
   100  // experimental.FunctionListener.
   101  func (f *loggingListenerFactory) NewFunctionListener(fnd api.FunctionDefinition) experimental.FunctionListener {
   102  	exported := len(fnd.ExportNames()) > 0
   103  	if f.hostOnly && // choose functions defined or callable by the host
   104  		fnd.GoFunction() == nil && // not defined by the host
   105  		!exported { // not callable by the host
   106  		return nil
   107  	}
   108  
   109  	var pLoggers []logging.ParamLogger
   110  	var pSampler logging.ParamSampler
   111  	var rLoggers []logging.ResultLogger
   112  	switch fnd.ModuleName() {
   113  	case wasip1.InternalModuleName:
   114  		if !wasilogging.IsInLogScope(fnd, f.scopes) {
   115  			return nil
   116  		}
   117  		pSampler, pLoggers, rLoggers = wasilogging.Config(fnd)
   118  	case "go", "gojs":
   119  		if !gologging.IsInLogScope(fnd, f.scopes) {
   120  			return nil
   121  		}
   122  		pSampler, pLoggers, rLoggers = gologging.Config(fnd, f.scopes)
   123  	case "env":
   124  		// env is difficult because the same module name is used for different
   125  		// ABI.
   126  		pLoggers, rLoggers = logging.Config(fnd)
   127  		switch fnd.Name() {
   128  		case "emscripten_notify_memory_growth":
   129  			if !logging.LogScopeMemory.IsEnabled(f.scopes) {
   130  				return nil
   131  			}
   132  		default:
   133  			if !aslogging.IsInLogScope(fnd, f.scopes) {
   134  				return nil
   135  			}
   136  		}
   137  	default:
   138  		// We don't know the scope of the function, so compare against all.
   139  		if f.scopes != logging.LogScopeAll {
   140  			return nil
   141  		}
   142  		pLoggers, rLoggers = logging.Config(fnd)
   143  	}
   144  
   145  	var before, after string
   146  	if fnd.GoFunction() != nil {
   147  		before = "==> " + fnd.DebugName()
   148  		after = "<=="
   149  	} else {
   150  		before = "--> " + fnd.DebugName()
   151  		after = "<--"
   152  	}
   153  	return &loggingListener{
   154  		w:            f.w,
   155  		beforePrefix: before,
   156  		afterPrefix:  after,
   157  		pLoggers:     pLoggers,
   158  		pSampler:     pSampler,
   159  		rLoggers:     rLoggers,
   160  		stack:        &f.stack,
   161  	}
   162  }
   163  
   164  type logStack struct {
   165  	params [][]uint64
   166  }
   167  
   168  func (s *logStack) push(params []uint64) {
   169  	s.params = append(s.params, params)
   170  }
   171  
   172  func (s *logStack) pop() []uint64 {
   173  	i := len(s.params) - 1
   174  	params := s.params[i]
   175  	s.params[i] = nil
   176  	s.params = s.params[:i]
   177  	return params
   178  }
   179  
   180  func (s *logStack) count() (n int) {
   181  	for _, p := range s.params {
   182  		if p != nil {
   183  			n++
   184  		}
   185  	}
   186  	return n
   187  }
   188  
   189  // loggingListener implements experimental.FunctionListener to log entrance and after
   190  // of each function call.
   191  type loggingListener struct {
   192  	w                         logging.Writer
   193  	beforePrefix, afterPrefix string
   194  	pLoggers                  []logging.ParamLogger
   195  	pSampler                  logging.ParamSampler
   196  	rLoggers                  []logging.ResultLogger
   197  	stack                     *logStack
   198  }
   199  
   200  // Before logs to stdout the module and function name, prefixed with '-->' and
   201  // indented based on the call nesting level.
   202  func (l *loggingListener) Before(ctx context.Context, mod api.Module, def api.FunctionDefinition, params []uint64, _ experimental.StackIterator) {
   203  	// First, see if this invocation is sampled.
   204  	sampled := true
   205  	if s := l.pSampler; s != nil {
   206  		sampled = s(ctx, mod, params)
   207  	}
   208  
   209  	if sampled {
   210  		l.logIndented(l.stack.count(), l.beforePrefix, func() {
   211  			l.logParams(ctx, mod, params)
   212  		})
   213  		params = append([]uint64{}, params...)
   214  	} else {
   215  		params = nil
   216  	}
   217  
   218  	l.stack.push(params)
   219  }
   220  
   221  // After logs to stdout the module and function name, prefixed with '<--' and
   222  // indented based on the call nesting level.
   223  func (l *loggingListener) After(ctx context.Context, mod api.Module, def api.FunctionDefinition, results []uint64) {
   224  	if params := l.stack.pop(); params != nil {
   225  		l.logIndented(l.stack.count(), l.afterPrefix, func() {
   226  			l.logResults(ctx, mod, params, results)
   227  		})
   228  	}
   229  }
   230  
   231  func (l *loggingListener) Abort(ctx context.Context, mod api.Module, def api.FunctionDefinition, _ error) {
   232  	l.stack.pop()
   233  }
   234  
   235  // logIndented writes an indentation level and prefix prior to calling log to
   236  // output the log line.
   237  func (l *loggingListener) logIndented(nestLevel int, prefix string, log func()) {
   238  	for i := 0; i < nestLevel; i++ {
   239  		l.w.WriteByte('\t') //nolint
   240  	}
   241  	l.w.WriteString(prefix) //nolint
   242  	log()
   243  	l.w.WriteByte('\n') //nolint
   244  
   245  	if f, ok := l.w.(flusher); ok {
   246  		f.Flush() //nolint
   247  	}
   248  }
   249  
   250  func (l *loggingListener) logParams(ctx context.Context, mod api.Module, params []uint64) {
   251  	paramLen := len(l.pLoggers)
   252  	l.w.WriteByte('(') //nolint
   253  	if paramLen > 0 {
   254  		l.pLoggers[0](ctx, mod, l.w, params)
   255  		for i := 1; i < paramLen; i++ {
   256  			l.w.WriteByte(',') //nolint
   257  			l.pLoggers[i](ctx, mod, l.w, params)
   258  		}
   259  	}
   260  	l.w.WriteByte(')') //nolint
   261  }
   262  
   263  func (l *loggingListener) logResults(ctx context.Context, mod api.Module, params, results []uint64) {
   264  	resultLen := len(l.rLoggers)
   265  	if resultLen == 0 {
   266  		return
   267  	}
   268  	l.w.WriteByte(' ') //nolint
   269  	switch resultLen {
   270  	case 1:
   271  		l.rLoggers[0](ctx, mod, l.w, params, results)
   272  	default:
   273  		l.w.WriteByte('(') //nolint
   274  		l.rLoggers[0](ctx, mod, l.w, params, results)
   275  		for i := 1; i < resultLen; i++ {
   276  			l.w.WriteByte(',') //nolint
   277  			l.rLoggers[i](ctx, mod, l.w, params, results)
   278  		}
   279  		l.w.WriteByte(')') //nolint
   280  	}
   281  }
   282
View as plain text