logging.go

Documentation: github.com/tetratelabs/wazero/internal/gojs/logging

     1  package logging
     2  
     3  import (
     4  	"context"
     5  	"fmt"
     6  	"io/fs"
     7  	"os"
     8  	"strconv"
     9  
    10  	"github.com/tetratelabs/wazero/api"
    11  	"github.com/tetratelabs/wazero/internal/gojs"
    12  	"github.com/tetratelabs/wazero/internal/gojs/custom"
    13  	"github.com/tetratelabs/wazero/internal/gojs/goarch"
    14  	"github.com/tetratelabs/wazero/internal/gojs/goos"
    15  	"github.com/tetratelabs/wazero/internal/logging"
    16  	"github.com/tetratelabs/wazero/internal/sys"
    17  )
    18  
    19  // IsInLogScope returns true if the current function is in any of the scopes.
    20  func IsInLogScope(fnd api.FunctionDefinition, scopes logging.LogScopes) bool {
    21  	if scopes.IsEnabled(logging.LogScopeClock) {
    22  		switch fnd.Name() {
    23  		case custom.NameRuntimeNanotime1, custom.NameRuntimeWalltime:
    24  			return true
    25  		case custom.NameSyscallValueCall: // e.g. Date.getTimezoneOffset
    26  			return true
    27  		}
    28  	}
    29  
    30  	if scopes.IsEnabled(logging.LogScopeProc) {
    31  		switch fnd.Name() {
    32  		case custom.NameRuntimeWasmExit:
    33  			return true
    34  		case custom.NameSyscallValueCall: // e.g. proc.*
    35  			return true
    36  		}
    37  	}
    38  
    39  	if scopes.IsEnabled(logging.LogScopeFilesystem) {
    40  		if fnd.Name() == custom.NameSyscallValueCall {
    41  			return true // e.g. fs.open
    42  		}
    43  	}
    44  
    45  	if scopes.IsEnabled(logging.LogScopeMemory) {
    46  		switch fnd.Name() {
    47  		case custom.NameRuntimeResetMemoryDataView:
    48  			return true
    49  		}
    50  	}
    51  
    52  	if scopes.IsEnabled(logging.LogScopePoll) {
    53  		switch fnd.Name() {
    54  		case custom.NameRuntimeScheduleTimeoutEvent, custom.NameRuntimeClearTimeoutEvent:
    55  			return true
    56  		}
    57  	}
    58  
    59  	if scopes.IsEnabled(logging.LogScopeRandom) {
    60  		switch fnd.Name() {
    61  		case custom.NameRuntimeGetRandomData:
    62  			return true
    63  		case custom.NameSyscallValueCall: // e.g. crypto.getRandomValues
    64  			return true
    65  		}
    66  	}
    67  
    68  	return scopes == logging.LogScopeAll
    69  }
    70  
    71  func Config(fnd api.FunctionDefinition, scopes logging.LogScopes) (pSampler logging.ParamSampler, pLoggers []logging.ParamLogger, rLoggers []logging.ResultLogger) {
    72  	switch fnd.Name() {
    73  	case custom.NameRuntimeWasmExit:
    74  		pLoggers = []logging.ParamLogger{runtimeWasmExitParamLogger}
    75  		// no results
    76  	case custom.NameRuntimeWasmWrite:
    77  		return // Don't log NameRuntimeWasmWrite as it is used in panics
    78  	case custom.NameRuntimeResetMemoryDataView:
    79  		// no params or results
    80  	case custom.NameRuntimeNanotime1:
    81  		// no params
    82  		rLoggers = []logging.ResultLogger{runtimeNanotime1ResultLogger}
    83  	case custom.NameRuntimeWalltime:
    84  		// no params
    85  		rLoggers = []logging.ResultLogger{runtimeWalltimeResultLogger}
    86  	case custom.NameRuntimeScheduleTimeoutEvent:
    87  		pLoggers = []logging.ParamLogger{runtimeScheduleTimeoutEventParamLogger}
    88  		rLoggers = []logging.ResultLogger{runtimeScheduleTimeoutEventResultLogger}
    89  	case custom.NameRuntimeClearTimeoutEvent:
    90  		pLoggers = []logging.ParamLogger{runtimeClearTimeoutEventParamLogger}
    91  		// no results
    92  	case custom.NameRuntimeGetRandomData:
    93  		pLoggers = []logging.ParamLogger{runtimeGetRandomDataParamLogger}
    94  		// no results
    95  	case custom.NameSyscallValueCall:
    96  		p := &syscallValueCallParamSampler{scopes: scopes}
    97  		pSampler = p.isSampled
    98  		pLoggers = []logging.ParamLogger{syscallValueCallParamLogger}
    99  		rLoggers = []logging.ResultLogger{syscallValueCallResultLogger}
   100  	default: // TODO: make generic logger for gojs
   101  	}
   102  	return
   103  }
   104  
   105  func runtimeGetRandomDataParamLogger(_ context.Context, mod api.Module, w logging.Writer, params []uint64) {
   106  	paramIdx := 1 /* there are two params, only write the length */
   107  	writeParameter(w, custom.NameRuntimeGetRandomData, mod, params, paramIdx)
   108  }
   109  
   110  func runtimeScheduleTimeoutEventParamLogger(_ context.Context, mod api.Module, w logging.Writer, params []uint64) {
   111  	writeParameter(w, custom.NameRuntimeScheduleTimeoutEvent, mod, params, 0)
   112  }
   113  
   114  func runtimeClearTimeoutEventParamLogger(_ context.Context, mod api.Module, w logging.Writer, params []uint64) {
   115  	writeParameter(w, custom.NameRuntimeClearTimeoutEvent, mod, params, 0)
   116  }
   117  
   118  func runtimeWasmExitParamLogger(_ context.Context, mod api.Module, w logging.Writer, params []uint64) {
   119  	writeParameter(w, custom.NameRuntimeWasmExit, mod, params, 0)
   120  }
   121  
   122  func writeParameter(w logging.Writer, funcName string, mod api.Module, params []uint64, paramIdx int) {
   123  	paramNames := custom.NameSection[funcName].ParamNames
   124  
   125  	stack := goos.NewStack(funcName, mod.Memory(), uint32(params[0]))
   126  	w.WriteString(paramNames[paramIdx]) //nolint
   127  	w.WriteByte('=')                    //nolint
   128  	writeI32(w, stack.ParamUint32(paramIdx))
   129  }
   130  
   131  func runtimeNanotime1ResultLogger(_ context.Context, mod api.Module, w logging.Writer, params, _ []uint64) {
   132  	writeResults(w, custom.NameRuntimeNanotime1, mod, params, 0)
   133  }
   134  
   135  func runtimeWalltimeResultLogger(_ context.Context, mod api.Module, w logging.Writer, params, _ []uint64) {
   136  	writeResults(w, custom.NameRuntimeWalltime, mod, params, 0)
   137  }
   138  
   139  func runtimeScheduleTimeoutEventResultLogger(_ context.Context, mod api.Module, w logging.Writer, params, _ []uint64) {
   140  	writeResults(w, custom.NameRuntimeScheduleTimeoutEvent, mod, params, 1)
   141  }
   142  
   143  func writeResults(w logging.Writer, funcName string, mod api.Module, params []uint64, resultOffset int) {
   144  	stack := goos.NewStack(funcName, mod.Memory(), uint32(params[0]))
   145  
   146  	resultNames := custom.NameSection[funcName].ResultNames
   147  	results := make([]interface{}, len(resultNames))
   148  	for i := range resultNames {
   149  		results[i] = stack.ParamUint32(i + resultOffset)
   150  	}
   151  
   152  	w.WriteByte('(') //nolint
   153  	writeVals(w, resultNames, results)
   154  	w.WriteByte(')') //nolint
   155  }
   156  
   157  type syscallValueCallParamSampler struct {
   158  	scopes logging.LogScopes
   159  }
   160  
   161  func (s *syscallValueCallParamSampler) isSampled(ctx context.Context, mod api.Module, params []uint64) bool {
   162  	vRef, m, args := syscallValueCallParams(ctx, mod, params)
   163  
   164  	switch vRef {
   165  	case goos.RefJsCrypto:
   166  		return logging.LogScopeRandom.IsEnabled(s.scopes)
   167  	case goos.RefJsDate:
   168  		return logging.LogScopeClock.IsEnabled(s.scopes)
   169  	case goos.RefJsfs:
   170  		if !logging.LogScopeFilesystem.IsEnabled(s.scopes) {
   171  			return false
   172  		}
   173  		// Don't amplify logs with stdio reads or writes
   174  		switch m {
   175  		case custom.NameFsWrite, custom.NameFsRead:
   176  			fd := goos.ValueToInt32(args[0])
   177  			return fd > sys.FdStderr
   178  		}
   179  		return true
   180  	case goos.RefJsProcess:
   181  		return logging.LogScopeProc.IsEnabled(s.scopes)
   182  	}
   183  
   184  	return s.scopes == logging.LogScopeAll
   185  }
   186  
   187  func syscallValueCallParamLogger(ctx context.Context, mod api.Module, w logging.Writer, params []uint64) {
   188  	vRef, m, args := syscallValueCallParams(ctx, mod, params)
   189  
   190  	switch vRef {
   191  	case goos.RefJsCrypto:
   192  		logSyscallValueCallArgs(w, custom.NameCrypto, m, args)
   193  	case goos.RefJsDate:
   194  		logSyscallValueCallArgs(w, custom.NameDate, m, args)
   195  	case goos.RefJsfs:
   196  		logFsParams(m, w, args)
   197  	case goos.RefJsProcess:
   198  		logSyscallValueCallArgs(w, custom.NameProcess, m, args)
   199  	default:
   200  		// TODO: other scopes
   201  	}
   202  }
   203  
   204  func logFsParams(m string, w logging.Writer, args []interface{}) {
   205  	if m == custom.NameFsOpen {
   206  		w.WriteString("fs.open(")       //nolint
   207  		w.WriteString("path=")          //nolint
   208  		w.WriteString(args[0].(string)) //nolint
   209  		w.WriteString(",flags=")        //nolint
   210  		writeOFlags(w, int(args[1].(float64)))
   211  		w.WriteString(",perm=")                                        //nolint
   212  		w.WriteString(fs.FileMode(uint32(args[2].(float64))).String()) //nolint
   213  		w.WriteByte(')')                                               //nolint
   214  		return
   215  	}
   216  
   217  	logSyscallValueCallArgs(w, custom.NameFs, m, args)
   218  }
   219  
   220  func logSyscallValueCallArgs(w logging.Writer, n, m string, args []interface{}) {
   221  	argNames := custom.NameSectionSyscallValueCall[n][m].ParamNames
   222  	w.WriteString(n) //nolint
   223  	w.WriteByte('.') //nolint
   224  	w.WriteString(m) //nolint
   225  	w.WriteByte('(') //nolint
   226  	writeVals(w, argNames, args)
   227  	w.WriteByte(')') //nolint
   228  }
   229  
   230  func syscallValueCallParams(ctx context.Context, mod api.Module, params []uint64) (goos.Ref, string, []interface{}) {
   231  	mem := mod.Memory()
   232  	funcName := custom.NameSyscallValueCall
   233  	stack := goos.NewStack(funcName, mem, uint32(params[0]))
   234  	vRef := stack.ParamRef(0)               //nolint
   235  	m := stack.ParamString(mem, 1 /*, 2 */) //nolint
   236  	args := stack.ParamVals(ctx, mem, 3 /*, 4 */, gojs.LoadValue)
   237  	return vRef, m, args
   238  }
   239  
   240  func syscallValueCallResultLogger(ctx context.Context, mod api.Module, w logging.Writer, params, results []uint64) {
   241  	mem := mod.Memory()
   242  	funcName := custom.NameSyscallValueCall
   243  	stack := goos.NewStack(funcName, mem, goarch.GetSP(mod))
   244  	vRef := stack.ParamRef(0)               //nolint
   245  	m := stack.ParamString(mem, 1 /*, 2 */) //nolint
   246  
   247  	var resultNames []string
   248  	var resultVals []interface{}
   249  	switch vRef {
   250  	case goos.RefJsCrypto:
   251  		resultNames = custom.CryptoNameSection[m].ResultNames
   252  		rRef := stack.ParamVal(ctx, 6, gojs.LoadValue) // val is after padding
   253  		resultVals = []interface{}{rRef}
   254  	case goos.RefJsDate:
   255  		resultNames = custom.DateNameSection[m].ResultNames
   256  		rRef := stack.ParamVal(ctx, 6, gojs.LoadValue) // val is after padding
   257  		resultVals = []interface{}{rRef}
   258  	case goos.RefJsfs:
   259  		resultNames = custom.FsNameSection[m].ResultNames
   260  		resultVals = gojs.GetLastEventArgs(ctx)
   261  	case goos.RefJsProcess:
   262  		resultNames = custom.ProcessNameSection[m].ResultNames
   263  		rRef := stack.ParamVal(ctx, 6, gojs.LoadValue) // val is after padding
   264  		resultVals = []interface{}{rRef}
   265  	default:
   266  		// TODO: other scopes
   267  	}
   268  
   269  	w.WriteByte('(') //nolint
   270  	writeVals(w, resultNames, resultVals)
   271  	w.WriteByte(')') //nolint
   272  }
   273  
   274  func writeVals(w logging.Writer, names []string, vals []interface{}) {
   275  	valLen := len(vals)
   276  	if valLen > 0 {
   277  		writeVal(w, names[0], vals[0])
   278  		for i := 1; i < valLen; i++ {
   279  			name := names[i]
   280  			val := vals[i]
   281  
   282  			switch name {
   283  			case custom.NameCallback:
   284  				return // last val
   285  			case "buf": // always equal size with byteCount
   286  				continue
   287  			}
   288  
   289  			w.WriteByte(',') //nolint
   290  			writeVal(w, name, val)
   291  		}
   292  	}
   293  }
   294  
   295  func writeVal(w logging.Writer, name string, val interface{}) {
   296  	if b, ok := val.(*goos.ByteArray); ok {
   297  		// Write the length instead of a byte array.
   298  		w.WriteString(name)                  //nolint
   299  		w.WriteString("_len=")               //nolint
   300  		writeI32(w, uint32(len(b.Unwrap()))) //nolint
   301  		return
   302  	}
   303  	switch name {
   304  	case "uid", "gid":
   305  		w.WriteString(name) //nolint
   306  		w.WriteByte('=')    //nolint
   307  		id := int(goos.ValueToInt32(val))
   308  		w.WriteString(strconv.Itoa(id)) //nolint
   309  	case "mask", "mode", "oldmask", "perm":
   310  		w.WriteString(name) //nolint
   311  		w.WriteByte('=')    //nolint
   312  		perm := custom.FromJsMode(goos.ValueToUint32(val), 0)
   313  		w.WriteString(perm.String()) //nolint
   314  	default:
   315  		w.WriteString(name)                   //nolint
   316  		w.WriteByte('=')                      //nolint
   317  		w.WriteString(fmt.Sprintf("%v", val)) //nolint
   318  	}
   319  }
   320  
   321  func writeOFlags(w logging.Writer, f int) {
   322  	// Iterate a subflagset in order to avoid OS differences, notably for windows
   323  	first := true
   324  	for i, sf := range oFlags {
   325  		if f&sf != 0 {
   326  			if !first {
   327  				w.WriteByte('|') //nolint
   328  			} else {
   329  				first = false
   330  			}
   331  			w.WriteString(oflagToString[i]) //nolint
   332  		}
   333  	}
   334  }
   335  
   336  var oFlags = [...]int{
   337  	os.O_RDONLY,
   338  	os.O_WRONLY,
   339  	os.O_RDWR,
   340  	os.O_APPEND,
   341  	os.O_CREATE,
   342  	os.O_EXCL,
   343  	os.O_SYNC,
   344  	os.O_TRUNC,
   345  }
   346  
   347  var oflagToString = [...]string{
   348  	"RDONLY",
   349  	"WRONLY",
   350  	"RDWR",
   351  	"APPEND",
   352  	"CREATE",
   353  	"EXCL",
   354  	"SYNC",
   355  	"TRUNC",
   356  }
   357  
   358  func writeI32(w logging.Writer, v uint32) {
   359  	w.WriteString(strconv.FormatInt(int64(int32(v)), 10)) //nolint
   360  }
   361
View as plain text