[Fluentd Setup]Some special Postgresql slow sql was not shown in Show statements

[qitongfire]

Search before asking

• I had searched in the issues and found no similar issues.

Apache SkyWalking Component

OAP server (apache/skywalking)

What happened

Our project wasing using skywalking to monitor Postgresql slow and found a problem: with "pg_sleep" as (select * from pg_sleep(1.4)) select * from "pg_sleep", This sql was not shown in Show statements, But this sql "with pg_sleep as (select * from pg_sleep(1.4)) select * from pg_sleep" display normally. I debuged running Skywalking oap, It could get a message("with pg_sleep as (select * from pg_sleep(1.4)) select * from pg_sleep"), But it is not stored in the Elasticsearch(We use elasticsearch as the store). That should be a problem.

NOTE:The Skywalking OAP did not show any problems

What you expected to happen

I expect this type of sql to display normally in the Slow statements(ex sql: with "pg_sleep" as (select * from pg_sleep(1.4)) select * from "pg_sleep"),

Skywalking version: 9.3.0,
fluent-bit version: 2.0.9

fluent-bit log:
[{"date":1677836101.832795,"body":{"json":{"json":"{"statement":" 1404.043 ms statement: with "pg_sleep" as (select * from pg_sleep(1.4)) select * from "pg_sleep";","query_time":1404,"service":"postgresql::postgres:5432","id":"34bacb9e-aea6-6246-49e5-14ace3d4848c","layer":"POSTGRESQL","time":1677836101000}"}},"tags":{"data":[{"value":"SLOW_SQL","key":"LOG_KIND"}]},"service":"postgresql::postgres:5432","layer":"POSTGRESQL"}]
[2023/03/03 17:36:44] [ info] [output:http:http.1] 10.255.13.133:12800, HTTP status=200

How to reproduce

Skywalking monitor Postgresql,
Enabling Postgresql slow
execute the following sql

sql:
with "pg_sleep" as (select * from pg_sleep(1.4)) select * from "pg_sleep"

Anything else

No response

Are you willing to submit PR?

• Yes I am willing to submit a PR!

Code of Conduct

• I agree to follow this project's Code of Conduct

[wu-sheng]

fluent-bit log:
[{"date":1677836101.832795,"body":{"json":{"json":"{"statement":" 1404.043 ms statement: with "pg_sleep" as (select * from pg_sleep(1.4)) select * from "pg_sleep";","query_time":1404,"service":"postgresql::postgres:5432","id":"34bacb9e-aea6-6246-49e5-14ace3d4848c","layer":"POSTGRESQL","time":1677836101000}"}},"tags":{"data":[{"value":"SLOW_SQL","key":"LOG_KIND"}]},"service":"postgresql::postgres:5432","layer":"POSTGRESQL"}]
[2023/03/03 17:36:44] [ info] [output:http:http.1] 10.255.13.133:12800, HTTP status=200

This seems not a legal JSON. " should be represented as \" in the JSON AFAIK.
So, first of all, this could be expected, rather than a bug.

Maybe need to enhance fluentd config? @yswdqz

[qitongfire]

fluent-bit log:
[{"date":1677836101.832795,"body":{"json":{"json":"{"statement":" 1404.043 ms statement: with "pg_sleep" as (select * from pg_sleep(1.4)) select * from "pg_sleep";","query_time":1404,"service":"postgresql::postgres:5432","id":"34bacb9e-aea6-6246-49e5-14ace3d4848c","layer":"POSTGRESQL","time":1677836101000}"}},"tags":{"data":[{"value":"SLOW_SQL","key":"LOG_KIND"}]},"service":"postgresql::postgres:5432","layer":"POSTGRESQL"}]
[2023/03/03 17:36:44] [ info] [output:http:http.1] 10.255.13.133:12800, HTTP status=200

This seems not a legal JSON. " should be represented as \" in the JSON AFAIK. So, first of all, this could be expected, rather than a bug.

Maybe need to enhance fluentd config? @yswdqz

This is log in flunt-bit:
[{"date":1677838462.133755,"body":{"json":{"json":"{"statement":" 1408.590 ms statement: with "pg_sleep" as (select * from pg_sleep(1.4)) select * from "pg_sleep";","query_time":1408,"service":"postgresql::postgres:5432","id":"4545983c-b9c4-ebae-4f7e-9e9ca35918de","layer":"POSTGRESQL","time":1677838462000}"}},"tags":{"data":[{"value":"SLOW_SQL","key":"LOG_KIND"}]},"service":"postgresql::postgres:5432","layer":"POSTGRESQL"}]

Skywalking oap can get messages normally and Flunt-bit and Skywalking OAP are normal(not show any problems)

[wu-sheng]

If you want to address issues, you could debug the log receiver by yourself.

[qitongfire]

If you want to address issues, you could debug the log receiver by yourself.

I debuged running Skywalking oap, It could get a slow sql json(json in the screenshot above), But the slow sql is not stored in the Elasticsearch. The problem is that Skywalking oap handle slow sql json

[wu-sheng]

This description doesn't help. We never process logs based on the content(SQL text).

[qitongfire]

This description doesn't help. We never process logs based on the content(SQL text).

In the Skyealking OAP,this step is normal, as follows:

but execute to this method(closure.call()), The code didn't continue to go down:

Normal logic should execute FilterSpec.extractor, But my debugging did not:

my sql: with "pg_sleep" as (select * from pg_sleep(1.4)) select * from "pg_sleep";

flunt-bit log:

You can try the sql I provided

[wu-sheng]

@kezhenxu94 Any guess from LAL engine perspective?

[yswdqz]

I have tested local, and the log of fluent-bit is :

[{"date":1678088131.451024,"tags":{"data":[{"key":"LOG_KIND","value":"SLOW_SQL"}]},"body":{"json":{"json":"{\"id\":\"cb9c1a5b-691e-fb2f-457a-9c72a392d9ed\",\"layer\":\"POSTGRESQL\",\"statement\":\"with \"pg_sleep\" as (select * from pg_sleep(1.4)) select * from \"pg_sleep\"\",\"time\":1678088131000,\"query_time\":1401,\"service\":\"postgresql::postgres:5432\"}"}},"layer":"POSTGRESQL","service":"postgresql::postgres:5432"}]

But your log is

And this seems to have some syntax problems

[qitongfire]

I have tested local, and the log of fluent-bit is :

[{"date":1678088131.451024,"tags":{"data":[{"key":"LOG_KIND","value":"SLOW_SQL"}]},"body":{"json":{"json":"{\"id\":\"cb9c1a5b-691e-fb2f-457a-9c72a392d9ed\",\"layer\":\"POSTGRESQL\",\"statement\":\"with \"pg_sleep\" as (select * from pg_sleep(1.4)) select * from \"pg_sleep\"\",\"time\":1678088131000,\"query_time\":1401,\"service\":\"postgresql::postgres:5432\"}"}},"layer":"POSTGRESQL","service":"postgresql::postgres:5432"}]

But your log is And this seems to have some syntax problems

It has nothing to do with what you're saying，this sql with pg_sleep as (select * from pg_sleep(1.4)) select * from pg_sleep can display in Slow statements

[qitongfire]

I have tested local, and the log of fluent-bit is :

[{"date":1678088131.451024,"tags":{"data":[{"key":"LOG_KIND","value":"SLOW_SQL"}]},"body":{"json":{"json":"{\"id\":\"cb9c1a5b-691e-fb2f-457a-9c72a392d9ed\",\"layer\":\"POSTGRESQL\",\"statement\":\"with \"pg_sleep\" as (select * from pg_sleep(1.4)) select * from \"pg_sleep\"\",\"time\":1678088131000,\"query_time\":1401,\"service\":\"postgresql::postgres:5432\"}"}},"layer":"POSTGRESQL","service":"postgresql::postgres:5432"}]

But your log is And this seems to have some syntax problems

It has nothing to do with what you're saying，this sql with pg_sleep as (select * from pg_sleep(1.4)) select * from pg_sleep can display in Slow statements

@yswdqz Did your local test slow sql display normally in the Slow statements?

[qitongfire]

Please help explain,

I have tested local, and the log of fluent-bit is :

[{"date":1678088131.451024,"tags":{"data":[{"key":"LOG_KIND","value":"SLOW_SQL"}]},"body":{"json":{"json":"{\"id\":\"cb9c1a5b-691e-fb2f-457a-9c72a392d9ed\",\"layer\":\"POSTGRESQL\",\"statement\":\"with \"pg_sleep\" as (select * from pg_sleep(1.4)) select * from \"pg_sleep\"\",\"time\":1678088131000,\"query_time\":1401,\"service\":\"postgresql::postgres:5432\"}"}},"layer":"POSTGRESQL","service":"postgresql::postgres:5432"}]

But your log is And this seems to have some syntax problems

It has nothing to do with what you're saying，this sql with pg_sleep as (select * from pg_sleep(1.4)) select * from pg_sleep can display in Slow statements

Please help explain,Thanks

[wu-sheng]

Moved to the discussion, as this isn't a clear bug for now. @zhouqt0528 Issue is for tracking known things.

[qitongfire]

@yswdqz my the log of flunt-bit:
[{"date":1678090783.779459,"body":{"json":{"json":"{"query_time":1404,"service":"postgresql::postgres:5432","id":"cb9c1a5b-691e-fb2f-457a-9c72a392d9ed","layer":"POSTGRESQL","time":1678090783000,"statement":"with "pg_sleep" as (select * from pg_sleep(1.4)) select * from "pg_sleep";"}"}},"layer":"POSTGRESQL","service":"postgresql::postgres:5432","tags":{"data":[{"value":"SLOW_SQL","key":"LOG_KIND"}]}}]

[yswdqz]

I found that, in FilterSpec#json

Because your json has a syntax error，so oap will set this log is should abort.
And it will abort in FilterSpec#extractor

[yswdqz]

The value of body.json.josn also need to be a legal json.

[qitongfire]

The value of body.json.josn also need to be a legal json.

I don't think oap can handle this kind of sql(with "pg_sleep" as (select * from pg_sleep(1.4)) select * from "pg_sleep")
This kind of sql no problem in Postgresql

[qitongfire]

@yswdqz I expect this kind of sql can be display normally in the Slow statements, We need it very much, thanks a lot

[yswdqz]

I have fixed it, #10489 .
Since I optimized the whole code structure by the way, many changes are useless.
Because you are probably using your own custom configuration, you can just add this line to fix it.