Trace configuration is not validated on session start [CORE6075]

[firebird-automations]

Submitted by: @pcisar

The trace configuration that is part of "start trace" API call is not parsed/validated on input. The configuration is parsed when other attachment will have something to trace and detect new trace session. At this point it's too late to report it correctly to the user. As this is not even logged in firebird.log, the final result is that all configuration errors are swallowed and trace produces no output.

Making an error (typo, missing parenthesis or other) in configuration is easy. User can even mistakenly send (correct because previously tested and working) configuration in Firebird 2.5 format to the Firebird 3.0. As engine just happily starts the trace session that does not report anything wrong at any time and just produces nothing, it could easily lead to deep frustration in search for cause of the problem. The issue is that configuration is NOT validated on input (start trace session request). Engine should validate it and refuse to start the trace session with good error description where the problem is.

This was verified on 3.0.4, but almost certainly affects all versions since 2.5 up to 4.0 beta 1.

Commits: 54221b3 ad6033e

[firebird-automations]

Commented by: @AlexPeshkoff

That's generic issue with our .conf files - historically, except errors, making engine operation absolutely impossible (like 2 different configurations for same database) nothing is reported.

[firebird-automations]

Commented by: @hvlad

> The trace configuration that is part of "start trace" API call is not parsed/validated on input.
> The configuration is parsed when other attachment will have something to trace and detect new trace session.

Correct

> At this point it's too late to report it correctly to the user. As this is not even logged in firebird.log, the final result
> is that all configuration errors are swallowed and trace produces no output.

This is not exactly so. Trace configuration parser ignored unknown lines until it finds correct section header.
All elements inside section are validated and errors is correctly reported into session output.

Examples:

a) use trace configuration in v2.5 format with Firebird 3

fbtrace-1.25.conf:
<database>
enabled = true

log\_connections = true

log\_errors = true
log\_warnings = true
log\_initfini = false

time\_threshold = 0

</database>

fbtracemgr -se inet://service_mgr -start -conf fbtrace-1.25.conf
isql xnet://s:\Temp\A.30.FDB

Result: fbtracemgr reports no error when session start, trace output is empty

b) use trace configuration in v3 format with unknown element inside database section

fbtrace-2.30.conf:

database {
enabled = true

sss = ddd

log\_connections = true

log\_errors = true
log\_warnings = true
log\_initfini = false

time\_threshold = 0

}

fbtracemgr -se inet://service_mgr -start -conf fbtrace-2.30.conf
isql xnet://s:\Temp\A.30.FDB

Result: fbtracemgr reports no error when session start, trace output is below:

Trace session ID 3 started
Error creating trace session for database "F:\FB2\FB30\OUTPUT_X64\SECURITY3.FDB":
error while parsing trace configuration
line 4: element "sss" is unknown

Error creating trace session for database "S:\TEMP\A.30.FDB":
error while parsing trace configuration
line 4: element "sss" is unknown

It is not ideal, agree, but it is not as bad as described at ticked.

[firebird-automations]

Modified by: @hvlad

assignee: Vlad Khorsun [ hvlad ]

[firebird-automations]

Commented by: @pcisar

I can't confirm that "fbtracemgr reports no error when session start,". How such error report looks like? In either case, there is no report. In first case, there is simply no output from fbtracemgr beyond "Trace session ID XXX started" which does not resemble an error report. In second case, there is an error report WHEN an ATTACHMENT attempts to report some trace output, but not sooner which could be for a long time (i.e. fbtracemgr happily shows "Trace session ID XXX started" and then prints what comes from service which happens to be textual error report). I seriously doubt that messages "Error creating trace session for database "F:\FB2\FB30\OUTPUT_X64\SECURITY3.FDB" etc. are NOT received as regular output from trace session (i.e. text fetched from running fb service).

btw, it will be interesting to see how such error reporting will hold together if other trace plugin that produces data in non-textual format would be used instead default one. It will IMHO crash and burn the poor trace client.

EDIT: Sorry, I read it wrongly (I read "reports an error" instead "reports no error"). Combination of small letters and tired eyes.

[firebird-automations]

Commented by: @hvlad

> I can't confirm that "fbtracemgr reports no error when session start,". How such error report looks like? In either case, there is no report.

Explain what you want to say. As for me "reports no error" and "there is no report" is the same.

> I seriously doubt that messages "Error creating trace session for database "F:\FB2\FB30\OUTPUT_X64\SECURITY3.FDB" etc. are NOT received as regular output from trace session (i.e. text fetched from running fb service).

It IS regular output of trace session. It is NOT an error, passed via status-vector (as there is no eror at isc_service_query itself).
Seems we not understand each other.

> it will be interesting to see how such error reporting will hold together if other trace plugin that produces data in non-textual format would be used instead default one.
> It will IMHO crash and burn the poor trace client.

fbtracemgr just reads bytes from trace session output and pass it to the stdout.
If such a bytes "crash" stdout - let it be so, what can we do against it ?

In any case, there should be non-standard trace client provided for use with non-standard trace plugin.

[firebird-automations]

Commented by: @hvlad

> Trace configuration parser ignored unknown lines until it finds correct section header.

It is fixed now.
I think, there is no more cases when error in trace configuration could be silently ignored.
If you know such a case - please provide me with it.

Now, to the second part of the issue:
> The issue is that configuration is NOT validated on input (start trace session request). Engine should validate it

the problem is that engine have no idea what is "trace configuration". Engine just passes its contents into trace object, created by trace plugin.
Trace plugin is independent entity.

To implement "engine validate trace configuration" we need to change trace plugin interface.
It is doable but - is it really necessary, taking into account that trace session anyway validates configuration and report found errors via trace output ?

[firebird-automations]

Commented by: @pcisar

Taking into account how services are implemented in Firebird, your solution is best as we could get thought. However, to adjust trace output parsers to properly identify and process these error reports (in fact everything that is not a trace event sent through service output), it's necessary that they have fixed, well defined (i.e. simply parseable) format. It would be also nice if this format/pattern would be documented.

[firebird-automations]

Commented by: @AlexPeshkoff

Pavel, may be I'm missing something trace-specific - but all services starting with 2.5 send errors not through output data stream but use status vector instead. I.e. there should not be problem with parsing errors from the output - they just should not be in that stream.

[firebird-automations]

Commented by: @hvlad

Alex,

yes, you missed that
- trace plugin and engine works independently
- trace plugin could report errors to the caller only
- the caller of trace plugin is traced attachment, not trace service
- trace plugin doesn't send data to the trace service, there is no direct connection between trace plugin and trace service, they works in different attachments and could be in different processes