Refactor to use new scope.Error method #2208

clayscode · 2022-11-01T16:19:15Z

This PR changes most instances where scope.Log is used to report an error to scope.Error in order to make sure errors occur at the correct log level.

scudette · 2022-11-02T01:51:49Z

The problem with this approach is that we use the Error() log as an indication that the collection should be marked as failed. A lot of errors are not really fatal so the use of Error() should be done judiciously only in cases where it is obvious that something went very wrong.

Probably the default level should be fine in most cases, or maybe use WARN or INFO but ERROR should be reserved to cases where it is really bad.

Errors should be used in cases where the user needs to pay attention to the collection. For example:

The collection timed out - user may need to adjust the timeout
The regex is invalid - user provided invalid input and may need to adjust
Yara rule failed to compile - the user provided an invalid yara rule

clayscode · 2022-11-02T02:13:51Z

Perhaps just scope.Warn then? Will have to slowly comb through everything to figure out what warrants halting the collection, but marking errors as WARN for now at least indicates something has gone wrong.

scudette

This is a great PR because it makes us think about what errors should be flagged for user attention. It is great to work through them and see what each error represents.

Some of the errors are not always obvious - sometimes they are critical other times not so much. Maybe we need a way for the VQL to elevate errors in particular scopes? So when we get a WARN it elevates it to an error? It has to be somewhat VQL dependent and use case dependent.

I went through the first part and I think we can summarise:

ExtractArgsWithContext - definitely an error but this is already taken care of
Permission checks - not an error maybe WARN level?
API errors not critical maybe WARN?
Compiling regex/yara definitely error

scudette · 2022-11-02T01:55:57Z

vql/common/clock.go

@@ -49,7 +49,7 @@ func (self ClockPlugin) Call(
 		arg := &ClockPluginArgs{}
 		err := arg_parser.ExtractArgsWithContext(ctx, scope, args, arg)
 		if err != nil {
-			scope.Log("clock: %v", err)
+			scope.Error("clock: %v", err)


These are probably fine for Error - it means the args are not valid somehow and may be a syntax error (BTW these are automatically marked as error anyway here

velociraptor/flows/logs.go

Line 80 in 2d77179

getLogErrorRegex(config_obj).FindStringIndex(row.Message) != nil {

scudette · 2022-11-02T01:57:32Z

vql/common/env.go

@@ -46,13 +46,13 @@ func (self *EnvFunction) Call(ctx context.Context,

 	err := vql_subsystem.CheckAccess(scope, acls.MACHINE_STATE)
 	if err != nil {
-		scope.Log("environ: %s", err)
+		scope.Error("environ: %s", err)


May not be a critical error - if running with lower privileges we do want to just ignore

scudette · 2022-11-02T01:58:34Z

vql/common/mail.go

@@ -149,7 +149,7 @@ func (self MailPlugin) Call(
 		// Send the email to Bob, Cora and Dan.
 		err = d.DialAndSend(m)
 		if err != nil {
-			scope.Log("mail: %v", err)
+			scope.Error("mail: %v", err)


may not be critical - can be an intermittant failure

scudette · 2022-11-02T02:00:15Z

vql/common/shell.go

@@ -121,19 +121,19 @@ func (self ShellPlugin) Call(

 		stdout_pipe, err := command.StdoutPipe()
 		if err != nil {
-			scope.Log("shell: no command to run")
+			scope.Error("shell: no command to run")


This is probably the wrong message :-)

IDK - is this critical or not? it might be or it might be intermittent (e.g. tool failed to download etc)

scudette · 2022-11-02T02:00:39Z

vql/common/yara.go

@@ -99,7 +100,7 @@ func (self YaraScanPlugin) Call(

 		err = vql_subsystem.CheckFilesystemAccess(scope, arg.Accessor)
 		if err != nil {
-			scope.Log("yara: %s", err.Error())
+			scope.Error("yara: %s", err.Error())


probably not critical error

scudette · 2022-11-02T02:05:17Z

vql/filesystem/tempfile.go

 		return false
 	}

 	dir, err := ioutil.TempDir("", "tmp")
 	if err != nil {
-		scope.Log("tempdir: %v", err)
+		scope.Error("tempdir: %v", err)


Not an error

scudette · 2022-11-02T02:07:55Z

vql/functions/lists.go

@@ -159,7 +159,7 @@ func (self *FilterFunction) Call(ctx context.Context,
 	if arg.Condition != "" {
 		lambda, err = vfilter.ParseLambda(arg.Condition)
 		if err != nil {
-			scope.Log("filter: Unable to compile lambda %s", arg.Condition)
+			scope.Error("filter: Unable to compile lambda %s", arg.Condition)


this is definitely an error

scudette · 2022-11-02T02:08:46Z

vql/functions/url.go

 		return false
 	}

 	if arg.Parse != "" {
 		result, err := url.Parse(arg.Parse)
 		if err != nil {
-			scope.Log("url: %v", err)
+			scope.Error("url: %v", err)


not critical

scudette · 2022-11-02T02:10:06Z

vql/networking/http_client.go

@@ -51,6 +51,14 @@ var (
 	mu sync.Mutex

 	proxyHandler = http.ProxyFromEnvironment
+
+	validHttpMethods = map[string]bool{


this one disappeared no? maybe you need to rebase?

Yeah, thought I did. Weird

scudette · 2022-11-02T02:10:36Z

vql/networking/http_client.go

@@ -368,7 +384,7 @@ func (self *_HttpPlugin) Call(
 				req, err = http.NewRequestWithContext(
 					ctx, method, arg.Url, strings.NewReader(arg.Data))
 				if err != nil {
-					scope.Log("%s: %v", self.Name(), err)
+					scope.Error("%s: %v", self.Name(), err)


these may or may not be errors?

scudette · 2022-11-02T02:20:17Z

I think the default level is DEFAULT and makes no practical difference from WARN. I guess we need to think about the purpose of the log levels:

ERROR: Do we need to draw attention to the collection? then error will cause it to fail - without a failed collection no one is going to look at them specifically
WARN should be something that might have gone wrong but might also be expected - the user has to trawl through the logs and filter on those just to see if there was anything noteworthy
INFO are expected messages useful to monitor progress in collection - they can usually be hidden but are nice to have when following the collection in the GUI
DEBUG those should normally be hidden but tell us things we need to know if we suspect something is not working right
DEFAULT are those that are not classified yet - maybe similar to INFO ?

clayscode · 2022-11-02T02:36:32Z

For most of the calls to scope.Log, it's because there's an error, but sometimes that's not the case. It'd be helpful to be able to differentiate between the two by just looking at the level.

I think it makes sense for the default level to be INFO, things that might be an issue are WARN, ERROR is reserved solely for showstoppers, and DEBUG is just highly verbose output you probably don't care about.

scudette · 2022-11-02T10:47:10Z

Yes agree 👍 this is a great way to put it.

clayscode added 3 commits October 31, 2022 10:07

Fix params and add http method validation

8fe095a

Merge branch 'master' of github.com:velocidex/velociraptor

9ed92e2

Refactor scope.Log to scope.Error

c3a1a1e

scudette reviewed Nov 2, 2022

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Refactor to use new scope.Error method #2208

Refactor to use new scope.Error method #2208

clayscode commented Nov 1, 2022

scudette commented Nov 2, 2022

clayscode commented Nov 2, 2022

scudette left a comment

scudette Nov 2, 2022

scudette Nov 2, 2022

scudette Nov 2, 2022

scudette Nov 2, 2022

scudette Nov 2, 2022

scudette Nov 2, 2022

scudette Nov 2, 2022

scudette Nov 2, 2022

scudette Nov 2, 2022

clayscode Nov 2, 2022

scudette Nov 2, 2022

scudette commented Nov 2, 2022

clayscode commented Nov 2, 2022

scudette commented Nov 2, 2022

Refactor to use new scope.Error method #2208

Are you sure you want to change the base?

Refactor to use new scope.Error method #2208

Conversation

clayscode commented Nov 1, 2022

scudette commented Nov 2, 2022

clayscode commented Nov 2, 2022

scudette left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

scudette commented Nov 2, 2022

clayscode commented Nov 2, 2022

scudette commented Nov 2, 2022