Issue Details (XML | Word | Printable)

Key: CORE-6075
Type: Bug Bug
Status: Open Open
Priority: Critical Critical
Assignee: Vlad Khorsun
Reporter: Pavel Cisar
Votes: 0
Watchers: 2
Operations

If you were logged in you would be able to see more operations.
Firebird Core

Trace configuration is not validated on session start

Created: 03/Jun/19 11:41 AM   Updated: 07/Jun/19 08:41 AM
Component/s: Engine
Affects Version/s: 3.0.4
Fix Version/s: None

QA Status: No test


 Description  « Hide
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.


 All   Comments   Change History   Subversion Commits      Sort Order: Ascending order - Click to sort in descending order
Alexander Peshkov added a comment - 03/Jun/19 01:13 PM
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.

Vlad Khorsun added a comment - 06/Jun/19 08:22 AM
> 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.

Pavel Cisar added a comment - 06/Jun/19 09:20 AM - edited
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.

Vlad Khorsun added a comment - 06/Jun/19 09:35 AM - edited
> 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.

Vlad Khorsun added a comment - 06/Jun/19 11:04 AM
> 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 ?

Pavel Cisar added a comment - 07/Jun/19 07:28 AM
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.

Alexander Peshkov added a comment - 07/Jun/19 08:06 AM
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.

Vlad Khorsun added a comment - 07/Jun/19 08:41 AM
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