WIP: Resolve "Improve logging and errors returned by GraphQL resolvers" - [closed]

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 13:45

Merges 365-improve-graphql-resolvers-logging-errors -> develop

Closes #365

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 14:52

added 1 commit

• dd6fa83b - Standardise GraphQL resolvers errors and logging (#365)

Compare with previous version

[ashleyvega]

In GitLab by @jeremyletang on Jul 15, 2019, 15:00

Seems like anywhere else the syntax: "market-id" is used instead of "market_id"

[ashleyvega]

In GitLab by @cdm on Jul 15, 2019, 15:02

Should be market-id :thumbsup:

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 15:03

noted.

[ashleyvega]

In GitLab by @jeremyletang on Jul 15, 2019, 15:03

Why change that to Debug ? this is an actual error that we are checking, I would keep the Error log here. I would expect to see this error message when running the node with a normal Error level, so it help figure out what is the problem down the stack. Same comment for all the changes in the file.

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 15:07

changed this line in version 2 of the diff

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 15:07

added 1 commit

• fdfabcfc - Fix punctuation in logging keys

Compare with previous version

[ashleyvega]

In GitLab by @jeremyletang on Jul 15, 2019, 15:07

I add this comment here, but it's valid for most of them. In this case we will log "ailed to load object(s) from store", with an error message which may not be very explicit, we do not know, and a party ID, while the actual function i actually suppose to deal with orders by party.

I would most like keep custom strings for all log message (I do think as well it looks more clearer to have the log message visible in the log directly.

[ashleyvega]

In GitLab by @jeremyletang on Jul 15, 2019, 15:07

Following my previous comment, the definied ErrSomethingBlah is great tho.

[ashleyvega]

In GitLab by @jeremyletang on Jul 15, 2019, 15:11

Well if we return a valid Interval + a non nil value, how is the caller supposed to make sure what behaviour to adopt ?

I would even use a default all the time here then returning both, as it's done on line 762 ?

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 15:13

I've done it this way because the source file+line should be included in the log message, e.g.

2019-07-15T14:48:06.552+0100    INFO    gateway.gql graphql/server.go:161   Stopping GraphQL based API

[ashleyvega]

In GitLab by @jeremyletang on Jul 15, 2019, 15:14

Not sure why marketID and partyID are renamed here, they are names like this in the schema.graphql file. would be nice to have them name the same, just for the sake of keeping naming in sync maybe.

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 15:15

Good point. I don't mind which we do (ignoring a nil candle or not) but we should be consistent.

[ashleyvega]

In GitLab by @jeremyletang on Jul 15, 2019, 15:15

let's not use the pointer defered here as they could be nil. This is a valid comment for all the other place we defer pointer in the file.

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 15:17

It's for consistency with the rest of the file.

I'd prefer marketID over market, but I took a very quick look and saw more of the latter than the former.

[ashleyvega]

In GitLab by @jeremyletang on Jul 15, 2019, 15:17

I don't think it's a valid reason, I prefer see the information directly in the log, because if not why not just display error code only instead like this:

2019-07-15T14:48:06.552+0100 INFO gateway.gql graphql/server.go:161 E4242

Also, while going through the log I would like to be able to search for specific in the logs, not a line number.

[ashleyvega]

In GitLab by @jeremyletang on Jul 15, 2019, 15:18

yes.

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 15:19

Indeed. Sometimes we have

if market != nil {
    mkt = *market
}

in which case I should use mkt (potentially an empty string) instead of *market (potentially nil).

[ashleyvega]

In GitLab by @jeremyletang on Jul 15, 2019, 15:19

Well I would keep it like it was as if inconsistent with the rest of the file, it is with the schema. we should probably change the rest of the file to reflect what the arguments are really in a following PR.

[ashleyvega]

In GitLab by @jeremyletang on Jul 15, 2019, 15:20

yea but in the current case I think we have the check before to get the value of the market. However is you use *market this can be nil, and deferring the pointer will panic at runtime. while using mkt will not.

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 15:21

changed this line in version 3 of the diff

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 15:21

added 1 commit

• 4e12a9ca - Avoid dereferencing potentially nil vars

Compare with previous version

[ashleyvega]

In GitLab by @jeremyletang on Jul 15, 2019, 15:21

This need to be updated as well to be account-type most likely

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 15:21

Fixed.

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 15:22

Done.

[ashleyvega]

In GitLab by @jeremyletang on Jul 15, 2019, 15:22

Also is that pendingorder order pending-order ?

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 15:22

Fixed.

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 15:23

I need do dig out the doc on log levels again ...

[ashleyvega]

In GitLab by @jeremyletang on Jul 15, 2019, 15:24

haha also, bot part of your PR, but just realise that this should be key, not "key". So if can be fixed at the same time, (btw I would not be surprised if I wrote that haha, that's the kind of stupid stuff I'm doing, I'm gonna git blame my self right now... haha)

[ashleyvega]

In GitLab by @jeremyletang on Jul 15, 2019, 15:24

haha yea it's me. such a genius.

[ashleyvega]

In GitLab by @jeremyletang on Jul 15, 2019, 15:25

well if you do not mind changing it as well at the same time ... cheers.

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 15:28

"If you choose to handle the error by logging it, by definition it’s not an error any more — you handled it. The act of logging an error handles the error, hence it is no longer appropriate to log it as an error."

https://dave.cheney.net/2015/11/05/lets-talk-about-logging

Also: "an overwhelming proportion of items logged at error level are simple done that way because they are related to an error."

I have come over to his way of thinking, which is that there are 2 useful log levels:

• Debug: Things that developers care about when they are developing or debugging software.
• Info: Things that users care about when using your software.

[ashleyvega]

In GitLab by @jeremyletang on Jul 15, 2019, 15:28

Why so ? Debug is higher level than Error, so if the node is setup to display only Error level (that I would except), these log would never show up. But they could happen for many reason which are actual error in the system. e.g, you running the gateway only, and it try to connect to the grpc server, which did not work, or the connection was lost, then you want to see an actual error (this is not and exact error that could happend for this exact for loop tho, but would be for all the code like this: res, err := r.tradingDataClient.Markets(ctx, &empty.Empty{}) which is also now set to be log.Debug)

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 15:29

Done.

[ashleyvega]

In GitLab by @jeremyletang on Jul 15, 2019, 15:30

yea this text is nice, I still think that an error in the system should be displayed when something like these happen. Even the user need to know that some setup is not right, or a connection was lost or whatever.

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 15:34

If (in the distant future) someone is running a Vega node and their app fails to talk to Vega over gRPC (or if they have any other high-level failure), then I would expect them to bump the log level to debug and retry, in order to see what's going on low-level.

If we classify these people as "users" rather than developers, then we should use Info level instead of Debug.

[ashleyvega]

In GitLab by @jeremyletang on Jul 15, 2019, 15:37

I still do not agree with that. i would expect anyone to be in Info level at anytime, which means that they can see error level. But only devs would go to Debug level, in order to get loads of information on how the system is behaving not specifically errors. I would expect any software to give me error message when shite happen.

Do you image ls having error silently, and beeing required to run ls --debug in order to get a no such file or directory error ? that sound quite wrong to me ?

[ashleyvega]

In GitLab by @jeremyletang on Jul 15, 2019, 15:38

Anyway I totally disagree with this change.

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 15:39

changed this line in version 4 of the diff

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 15:39

changed this line in version 4 of the diff

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 15:39

changed this line in version 4 of the diff

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 15:39

added 3 commits

• 33b61785 - Fix more punctuation
• 1f1101e8 - Fix typo
• 7bafeb1c - Handle problems with Candle intervals consistently

Compare with previous version

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 15:39

Fixed.

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 15:42

I don't mind either way. Object-wise, Market.ID --> market-id because the ID is a property of the Market. But a pending order is one object, rather than order being a property of pending.

[ashleyvega]

In GitLab by @jeremyletang on Jul 15, 2019, 15:44

to be honest I'm not sure if there's an actual rule in here about when to add the hypen or not, I thought we added it as soon as it was a composed word. but if it is when we reference properties, then it makes sense. in which case I would even more use a dot then market.id

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 15:48

Regarding your question about ls, I expect it to have many internal errors which do not affect me, hence are not logged to the terminal.

Just try strace ls / 2>&1 | grep -F ' = -1 E' :

access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
statfs("/sys/fs/selinux", 0x7ffeaf0c28e0) = -1 ENOENT (No such file or directory)
statfs("/selinux", 0x7ffeaf0c28e0)      = -1 ENOENT (No such file or directory)
ioctl(1, TCGETS, 0x7ffeaf0c2540)        = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(1, TIOCGWINSZ, 0x7ffeaf0c2600)    = -1 ENOTTY (Inappropriate ioctl for device)

All these "errors", and yet ls worked.

If, however, you run strace ls /DIR_THAT_DOES_NOT_EXIST 2>&1 | grep -F ' = -1 E' then we have extra errors, some of which are bubbled up and are printed on the console, because the user wants to see them.

[ashleyvega]

In GitLab by @jeremyletang on Jul 15, 2019, 15:54

that is totally different than what actually happen in our use case. These error you list are errors which happend true, but are not going against the usability of the program, also the request you asked for explicitly listing everything in / worked, some file are just most likely not allowed for you to be seen, but that do not break the execution of the command.

Try to run ls asdaksdihasdji and tell me it does not give you an error message. I explicitly ask for something, it did not work, I get a dump of an error.

That is the same use case in our code. We try to make a connection. to another party, which is mandatory for the software we execute, and it did not work. I want to be able to see it directly, without changing the default config, or restarting the node or whatever, this is nonsense to me.

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 15:57

I have the ls /DIR_THAT_DOES_NOT_EXIST example, if you read my comment to the end.

[ashleyvega]

In GitLab by @jeremyletang on Jul 15, 2019, 15:58

Also I think you misunderstood the article

err := somethingHard()
if err != nil {
        log.Error("oops, something was too hard", err)
        return err // what is this, Java ?
}

here the dude is logging, then returning the same error.

In our case, you don't handle the error, and return a new one.

[ashleyvega]

In GitLab by @ashleyvega on Jul 15, 2019, 16:00

If a request comes in for something that does not exist (e.g. curl https://geo.d.vega.xyz/markets/MarketMcMarketFace), then the user should already see a helpful message (e.g. { "code": 2, "message": "Key not found", "details": [] }).

I don't see the point of logging that at Error level.