Add log level config

[steve-chavez]

Add the log-level config option. The admitted values are:

• crit: No requests are logged. Only startup and db connection recovery messages are logged.
• error: Only failed requests(status >=400) are logged.
• info: All requests are logged. This is the only level we've been offering until now.

Partly addresses: #540 (debug level for another PR).

Perf

According to my load tests, the lower levels give more requests per second:

• crit: 208 req/s more on average.
• error: 170 req/s more on average.

Which makes sense because our default info level doesn't buffer the log messages. It writes them to disk, directly.
The error level is a bit slower because of the status filtering.

Changing the default log level

• Should we change the default log level to error? It certainly looks better for production.
• When PostgREST is behind nginx, the access.log already contains the logged requests. In these cases the crit level could be used. Since we're usually behind a proxy, perhaps we could default to crit instead?

[wolfgangwalther]

* When PostgREST is behind nginx, the `access.log` already contains the logged requests. In these cases the `crit` level could be used. Since we're usually behind a proxy, perhaps we could default to `crit` instead?

+1 for making crit the default.

Personally I have never used the logging output of postgrest so far, except for everything that's there with crit. I'd be using debug a lot more as well, but I usually find the request logging quite useless, because I do that on the client-side during development (in the browser) with a lot more detail.

Over in #1596 a distinction between errors in the 4xx and in the 5xx range is made. I think that makes a lot of sense. Imho, everything in the 4xx range is more or less expected (or at least handled properly), while those errors in 5xx deserve a lot more attention. Do you think it's possible to make a difference here?

I would probably turn on crit+5xx instead of crit, if available.

If this distinction makes sense to you as well, it could be like this:

• crit: same thing that you do now.
• error: crit + 5xx
• warning: error + 4xx
• info: all requests
• debug: + sql

(In that case, I would tend to make error the default)

[steve-chavez]

I think that makes a lot of sense. Imho, everything in the 4xx range is more or less expected (or at least handled properly), while those errors in 5xx deserve a lot more attention.

• crit: same thing that you do now.
• error: crit + 5xx
• warning: error + 4xx
• info: all requests
• debug: + sql

Good call! I'll add the warning level.

(In that case, I would tend to make error the default)

So do you think we should have error(crit + 5xx) as the default?

I'm tempted to make crit the default because it plays better with nginx(production setup) and gives more req/s.

[wolfgangwalther]

I'm tempted to make crit the default because it plays better with nginx(production setup) and gives more req/s.

My reasoning to make error (crit+5xx) the default would be:

• I expect 5xx errors to be something that should NOT happen in regular usage (i.e. when all is good) - when 5xx is thrown, something bad happens and I need to know that it does
• I expect the performance to only suffer when logging is actually happening. I might be wrong here - it depends a bit on whether your benchmark had errors in it as well, or not. In any case if only the decision to log an error or not is decreasing performance already - that seems odd to me. Can we do better here?
• If enough 5xx errors pile up to seriously harm performance - I have a way bigger problem than my performance to deliver those errors responses.

[steve-chavez]

@wolfgangwalther Totally agree on the reasoning for making error the default. I've made the changes.

I expect the performance to only suffer when logging is actually happening. I might be wrong here - it depends a bit on whether your benchmark had errors in it as well, or not.

No errors on the benchmark - one single req is tested and non-200 are checked.

In any case if only the decision to log an error or not is decreasing performance already - that seems odd to me. Can we do better here?

I think the next step for this would be adding the pgrstFormat logic on the wai-extra package. We could get feedback there on how to make it faster.

For now I'm happy with the results. Let me know if you agree and I'll merge :)

[wolfgangwalther]

LGTM!

[steve-chavez]

(ci/circlei: stack-test failed because io-tests are flaky:Received "segmentation fault" signal. Should be good to merge).

[elimisteve]

log-level = "debug" would be great; been trying to fix invalid input syntax for integer: "" for a week now. It's seemingly caused by a race condition -- potentially in PostgREST itself -- since the same exact request sometimes triggers the error and sometimes doesn't.

If it'd slow things down too much and just show what's in postgres's access logs anyway, I understand not adding "debug" as an option.

[steve-chavez]

log-level = "debug" would be great; been trying to fix invalid input syntax for integer: "" for a week now
It's seemingly caused by a race condition -- potentially in PostgREST itself -- since the same exact request sometimes triggers the error and sometimes doesn't.

@elimisteve Sorry, this somehow fell off my radar. I've actually seen that before, but thought it was an user error. Please open an issue if you encounter it again so we can track it.

If it'd slow things down too much and just show what's in postgres's access logs anyway, I understand not adding "debug" as an option.

debug is definitely in the plans. This week we'll release v8, then we'll look into this.