Getting stuck when trying to read output from a trace session

[qweqq]

Hello!

I am trying to read the output from a trace session, but it looks like the readline() call blocks indefinitely. This is the snippet I am using to reproduce the issue on a fresh Firebird install with firebird 3.0.7 on Debian 11:

from multiprocessing import Process
import time

srv_cfg = """\
[local]
    host = localhost
    user = SYSDBA
    password = masterkey
"""

db_cfg = """\
[employee]
    server = local
    database = employee.fdb
    protocol = inet
"""

def start_tracing():
    from firebird.driver import driver_config, connect_server

    driver_config.register_server('local', srv_cfg)
    driver_config.register_database('employee', db_cfg)

    trace_config = """\
database
{
    max_log_size = 123123123
    log_statement_prepare = false
    log_statement_start = true
    log_statement_finish = false
    log_procedure_start = true
    log_procedure_finish = false
    log_function_start = true
    log_function_finish = false
    log_trigger_start = true
    log_trigger_finish = false
    log_initfini = false
    log_dyn_requests = true
    max_sql_length = 30000
    max_dyn_length = 20000
    max_arg_length = 300
    max_arg_count = 100
}
services 
{
}
database = %
{
    enabled = true
}
"""

    with connect_server('local') as srv:
        trace_id = srv.trace.start(config=trace_config, name='test_trace_1')
        trace_log = []

        for i in range(10):
            print('trying to read a line...')
            trace_log.append(srv.readline())

        with connect_server('local') as srv_aux:
            srv_aux.trace.stop(session_id=trace_id)

def start_work():
    from firebird.driver import driver_config, connect

    driver_config.register_server('local', srv_cfg)
    driver_config.register_database('employee', db_cfg)

    with connect('employee') as con:
        cur = con.cursor()
        for i in range(0, 10):
            cur.execute("select country, currency from country")
            print('sql worker process: fetched %d rows' % len(cur.fetchall()))
            time.sleep(1)


if __name__ == '__main__':
    p_trace = Process(target=start_tracing, args=())
    p_trace.start()

    time.sleep(5)

    p_work = Process(target=start_work, args=())
    p_work.start()

    p_work.join()
    p_trace.join()

When running the same trace config via fbtracemgr it works:

fbtracemgr -service localhost:service_mgr -user SYSDBA -pass masterkey -name test -start -config test-trace.conf

Should I do something different in the python code to get it working ?

P.S This is my test virtualenv with python 3.9:

firebird-base==1.3.1
firebird-driver==1.4.3
protobuf==3.20.1
python-dateutil==2.8.2
six==1.16.0

Regards,
Hristo Stefanov

[AlexPeshkoff]

On 22.04.2022 12:06, Hristo Stefanov wrote: When running the same trace config via |fbtracemgr| it works: fbtracemgr -service localhost:service_mgr -user SYSDBA -pass masterkey -nametest -start -config test-trace.conf Should I do something different in the python code to get it working ?

Add timeout when calling readline (do not know how this to be done when using python - but should be possible).

…

P.S This is my test virtualenv with python 3.9: |firebird-base==1.3.1 firebird-driver==1.4.3 protobuf==3.20.1 python-dateutil==2.8.2 six==1.16.0 | Regards, Hristo Stefanov — Reply to this email directly, view it on GitHub <#11>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AA44OUJGI4F2QN4VD2IA2DTVGJT2DANCNFSM5UBVON6Q>. You are receiving this because you are subscribed to this thread.Message ID: ***@***.***>

[qweqq]

@AlexPeshkoff Thanks, your suggestion worked - if I add 1 second timeout the first call seems to timeout but then the next one succeeds. I guess when reading from a Trace session you should always read with a timeout set and tolerate the timeouts (when looking at the code for fbtracemgr this is what it does) ?

I opened a draft pull request that adds support for specifying an optional timeout for readline() here #12. I am not sure if this is the correct way to do it but it works.

[pcisar]

As I explained in response to your PR #12 , the firebird-driver can't support timeout for readline(). Reading service output always blocks, and this is consistent across the history since KInterbasDB, FDB and now firebird-driver. It has some specific consequences for trace (only), but nothing that couldn't be handled, it's just not possible to start + end trace session from within single function like in your example. You can either stop the trace from another process/thread, or use context manager like Firebird QA plugin - look for Action.trace().

As this is trace specific problem, I might extend ServerTraceServices class with specific method to query trace session output with timeout in some future driver version.

[qweqq]

@pcisar After going through the Firebird QA Plugin code you linked and with further experiments it turns out the problem with the code example I posted is that the Firebird server does not start sending trace messages immediately - it buffers them and after the buffer starts filling up it then starts sending them to the trace session.

So, if in the example code I change the number of executed statements to 1000 it works as expected - it shows the first 10 lines of the trace session and shuts it down successfully.

A way to request data from the buffer before it fills up sufficiently is by adding a timeout as @AlexPeshkoff suggested (verified this by compiling fbtracemgr without timeout and it starts blocking the same way as the python code), but as you pointed out it is not trivial to implement correctly.

[pcisar]

@qweqq It depends on MODE for queries for service output. The default is TO_EOF, but you may also set it to LINE. When TO_EOF is requested, firebird does not return from API call until the output buffer is full (firebird-driver uses 64K buffer). With LINE mode, the API call returns with single line of output (when is available).

[AlexPeshkoff]

On 4/24/22 18:26, Pavel Císař wrote: As I explained in response to your PR #12 <#12> , the firebird-driver can't support timeout for readline(). Reading service output always blocks, and this is consistent across the history since KInterbasDB, FDB and now firebird-driver. It has some specific consequences for trace (only), but nothing that couldn't be handled, it's just not possible to start + end trace session from within single function like in your example. You can either stop the trace from another process/thread, or use context manager like Firebird QA plugin <https://github.com/FirebirdSQL/firebird-qa/blob/master/firebird/qa/plugin.py> - look for Action.trace(). As this is trace specific problem, I might extend ServerTraceServices class with specific method to query trace session output with timeout in some future driver version.

That will be correct way to go - trace service is specific and differs from all the others, query never ends itself with the end of server thread, providing data to that query. Default timeout of 1 sec appears correct and good here.

[pcisar]

Service output query with timeout was added in version 1.8.0. See Server.readline_timed