Skip to content

Commit c47b9ce

Browse files
pcisarpcisar
authored
Merge pull request #6 from fdcastel/fix-issue-2
Improves the trace sessions parser's resilience. Fix #2.
2 parents 9610f67 + ca742e9 commit c47b9ce

File tree

2 files changed

+238
-27
lines changed

2 files changed

+238
-27
lines changed

‎src/firebird/lib/trace.py‎

Lines changed: 54 additions & 27 deletions
Original file line numberDiff line numberDiff line change
@@ -1253,7 +1253,15 @@ def _parse_transaction_performance(self) -> None:
12531253
self.__event_values['marks'] = None
12541254
if self.__current_block:
12551255
for value in self.__current_block.popleft().split(','):
1256-
value, val_type = value.split() # noqa: PLW2901
1256+
value = value.strip()
1257+
if not value:
1258+
# Skip empty values from trailing/leading commas
1259+
continue
1260+
parts = value.split()
1261+
if len(parts) != 2:
1262+
# Skip malformed performance values
1263+
continue
1264+
value, val_type = parts # noqa: PLW2901
12571265
if 'ms' in val_type:
12581266
self.__event_values['run_time'] = int(value)
12591267
elif 'read' in val_type:
@@ -1264,8 +1272,6 @@ def _parse_transaction_performance(self) -> None:
12641272
self.__event_values['fetches'] = int(value)
12651273
elif 'mark' in val_type:
12661274
self.__event_values['marks'] = int(value)
1267-
else:
1268-
raise Error(f"Unhandled performance parameter {val_type}")
12691275
def _parse_attachment_and_transaction(self) -> None:
12701276
# Attachment
12711277
att_values = {}
@@ -1353,11 +1359,23 @@ def _parse_value_spec(self, param_def: str) -> tuple[str, Any]:
13531359
elif param_type in ('smallint', 'integer', 'bigint'):
13541360
param_value = int(param_value)
13551361
elif param_type == 'timestamp':
1356-
param_value = datetime.datetime.strptime(param_value, '%Y-%m-%dT%H:%M:%S.%f') # noqa: DTZ007
1362+
try:
1363+
param_value = datetime.datetime.strptime(param_value, '%Y-%m-%dT%H:%M:%S.%f') # noqa: DTZ007
1364+
except ValueError:
1365+
# Handle malformed timestamps
1366+
pass
13571367
elif param_type == 'date':
1358-
param_value = datetime.datetime.strptime(param_value, '%Y-%m-%d') # noqa: DTZ007
1368+
try:
1369+
param_value = datetime.datetime.strptime(param_value, '%Y-%m-%d') # noqa: DTZ007
1370+
except ValueError:
1371+
# Handle malformed dates
1372+
pass
13591373
elif param_type == 'time':
1360-
param_value = datetime.datetime.strptime(param_value, '%H:%M:%S.%f') # noqa: DTZ007
1374+
try:
1375+
param_value = datetime.datetime.strptime(param_value, '%H:%M:%S.%f') # noqa: DTZ007
1376+
except ValueError:
1377+
# Handle malformed times
1378+
pass
13611379
elif param_type in ('float', 'double precision'):
13621380
param_value = decimal.Decimal(param_value)
13631381
return (param_type, param_value,)
@@ -1399,10 +1417,18 @@ def _parse_performance(self) -> None:
13991417
self.__event_values['records'] = int(line.split()[0])
14001418
else:
14011419
self.__event_values['records'] = None
1402-
values = self.__current_block.popleft().split(',')
1420+
perf_line = self.__current_block.popleft()
1421+
values = perf_line.split(',')
14031422
while values:
1404-
next_value = values.pop()
1405-
value, val_type = next_value.split()
1423+
next_value = values.pop().strip()
1424+
if not next_value:
1425+
# Skip empty values from trailing/leading commas
1426+
continue
1427+
parts = next_value.split()
1428+
if len(parts) != 2:
1429+
# Skip malformed performance values
1430+
continue
1431+
value, val_type = parts
14061432
if 'ms' in val_type:
14071433
self.__event_values['run_time'] = int(value)
14081434
elif 'read' in val_type:
@@ -1413,25 +1439,26 @@ def _parse_performance(self) -> None:
14131439
self.__event_values['fetches'] = int(value)
14141440
elif 'mark' in val_type:
14151441
self.__event_values['marks'] = int(value)
1416-
else:
1417-
raise Error(f"Unhandled performance parameter {val_type}")
14181442
if self.__current_block:
1419-
self.__event_values['access'] = []
1420-
if self.__current_block.popleft() != "Table Natural Index Update Insert Delete Backout Purge Expunge":
1421-
raise Error("Performance table header expected")
1422-
if self.__current_block.popleft() != "*"*111:
1423-
raise Error("Performance table header separator expected")
1424-
while self.__current_block:
1425-
entry = self.__current_block.popleft()
1426-
self.__event_values['access'].append(AccessStats(intern(entry[:32].strip()),
1427-
safe_int(entry[32:41].strip()),
1428-
safe_int(entry[41:51].strip()),
1429-
safe_int(entry[51:61].strip()),
1430-
safe_int(entry[61:71].strip()),
1431-
safe_int(entry[71:81].strip()),
1432-
safe_int(entry[81:91].strip()),
1433-
safe_int(entry[91:101].strip()),
1434-
safe_int(entry[101:111].strip())))
1443+
# Check if this is actually a table header before trying to parse it
1444+
next_line = self.__current_block[0]
1445+
if "Table" in next_line and "Natural" in next_line:
1446+
self.__event_values['access'] = []
1447+
if self.__current_block.popleft() != "Table Natural Index Update Insert Delete Backout Purge Expunge":
1448+
raise Error("Performance table header expected")
1449+
if self.__current_block.popleft() != "*"*111:
1450+
raise Error("Performance table header separator expected")
1451+
while self.__current_block:
1452+
entry = self.__current_block.popleft()
1453+
self.__event_values['access'].append(AccessStats(intern(entry[:32].strip()),
1454+
safe_int(entry[32:41].strip()),
1455+
safe_int(entry[41:51].strip()),
1456+
safe_int(entry[51:61].strip()),
1457+
safe_int(entry[61:71].strip()),
1458+
safe_int(entry[71:81].strip()),
1459+
safe_int(entry[81:91].strip()),
1460+
safe_int(entry[91:101].strip()),
1461+
safe_int(entry[101:111].strip())))
14351462
def _parse_sql_info(self) -> None:
14361463
plan = self.__event_values['plan']
14371464
sql = self.__event_values['sql']

‎tests/test_trace.py‎

Lines changed: 184 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -329,3 +329,187 @@ def test_62_unknown():
329329
EventUnknown(event_id=2, timestamp=datetime.datetime(2018, 3, 22, 10, 6, 59, 509000), data='EVENT_FROM_THE_FUTURE\\nThis event may contain\\nvarious information\\nwhich could span\\nmultiple lines.\\nYes, it could be very long!')
330330
"""
331331
_check_events(trace_lines, output)
332+
333+
def test_63_malformed_performance_trailing_comma():
334+
"""Tests parsing of EXECUTE_STATEMENT_FINISH with malformed performance data (trailing comma).
335+
336+
This test verifies the fix for the issue where performance lines with trailing commas
337+
or empty values caused "ValueError: not enough values to unpack (expected 2, got 1)".
338+
339+
Issue: Some Firebird trace files contain performance lines like:
340+
"123 ms, 456 reads, " (trailing comma with no value)
341+
"123 ms, , 789 fetches" (empty value between commas)
342+
343+
The parser now skips empty or malformed performance values instead of crashing.
344+
"""
345+
trace_lines = """2014-05-23T11:00:28.5840 (3720:0000000000EFD9E8) ATTACH_DATABASE
346+
/home/employee.fdb (ATT_8, SYSDBA:NONE, ISO88591, TCPv4:192.168.1.5)
347+
/opt/firebird/bin/isql:8723
348+
349+
2014-05-23T11:00:28.6160 (3720:0000000000EFD9E8) START_TRANSACTION
350+
/home/employee.fdb (ATT_8, SYSDBA:NONE, ISO88591, TCPv4:192.168.1.5)
351+
/opt/firebird/bin/isql:8723
352+
(TRA_1568, READ_COMMITTED | REC_VERSION | WAIT | READ_WRITE)
353+
354+
2014-05-23T11:00:30.4350 (3720:0000000000EFD9E8) EXECUTE_STATEMENT_FINISH
355+
/home/employee.fdb (ATT_8, SYSDBA:NONE, ISO88591, TCPv4:192.168.1.5)
356+
/opt/firebird/bin/isql:8723
357+
(TRA_1568, READ_COMMITTED | REC_VERSION | WAIT | READ_WRITE)
358+
359+
Statement 1:
360+
-------------------------------------------------------------------------------
361+
SELECT * FROM EMPLOYEE
362+
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
363+
0 records fetched
364+
15 ms, 147 read(s), 1 write(s), 6 fetch(es),
365+
366+
"""
367+
# The performance line has a trailing comma with no value after "fetch(es)"
368+
# The parser should skip the empty value and successfully parse the valid metrics
369+
output = """EventAttach(event_id=1, timestamp=datetime.datetime(2014, 5, 23, 11, 0, 28, 584000), status=<Status.OK: ' '>, attachment_id=8, database='/home/employee.fdb', charset='ISO88591', protocol='TCPv4', address='192.168.1.5', user='SYSDBA', role='NONE', remote_process='/opt/firebird/bin/isql', remote_pid=8723)
370+
EventTransactionStart(event_id=2, timestamp=datetime.datetime(2014, 5, 23, 11, 0, 28, 616000), status=<Status.OK: ' '>, attachment_id=8, transaction_id=1568, options=['READ_COMMITTED', 'REC_VERSION', 'WAIT', 'READ_WRITE'])
371+
SQLInfo(sql_id=1, sql='SELECT * FROM EMPLOYEE', plan='')
372+
EventStatementFinish(event_id=3, timestamp=datetime.datetime(2014, 5, 23, 11, 0, 30, 435000), status=<Status.OK: ' '>, attachment_id=8, transaction_id=1568, statement_id=1, sql_id=1, param_id=None, records=0, run_time=15, reads=147, writes=1, fetches=6, marks=None, access=None)
373+
"""
374+
_check_events(trace_lines, output)
375+
376+
def test_64_malformed_performance_empty_value():
377+
"""Tests parsing with performance data containing empty values between commas.
378+
379+
This test verifies that the parser can handle performance lines with empty values
380+
in the middle, such as "123 ms, , 789 fetches" where there's an empty value
381+
between two commas.
382+
"""
383+
trace_lines = """2014-05-23T11:00:28.5840 (3720:0000000000EFD9E8) ATTACH_DATABASE
384+
/home/employee.fdb (ATT_8, SYSDBA:NONE, ISO88591, TCPv4:192.168.1.5)
385+
/opt/firebird/bin/isql:8723
386+
387+
2014-05-23T11:00:28.6160 (3720:0000000000EFD9E8) START_TRANSACTION
388+
/home/employee.fdb (ATT_8, SYSDBA:NONE, ISO88591, TCPv4:192.168.1.5)
389+
/opt/firebird/bin/isql:8723
390+
(TRA_1568, READ_COMMITTED | REC_VERSION | WAIT | READ_WRITE)
391+
392+
2014-05-23T11:00:30.4350 (3720:0000000000EFD9E8) EXECUTE_PROCEDURE_FINISH
393+
/home/employee.fdb (ATT_8, SYSDBA:NONE, ISO88591, TCPv4:192.168.1.5)
394+
/opt/firebird/bin/isql:8723
395+
(TRA_1568, READ_COMMITTED | REC_VERSION | WAIT | READ_WRITE)
396+
397+
Procedure STP_READCONFIG:
398+
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
399+
10 ms, , 25 fetch(es)
400+
401+
"""
402+
# The performance line has an empty value between the first and second comma
403+
# The parser should skip the empty value and parse the valid metrics
404+
# Note: EXECUTE_PROCEDURE_FINISH events don't have statement_id/sql_id fields
405+
output = """EventAttach(event_id=1, timestamp=datetime.datetime(2014, 5, 23, 11, 0, 28, 584000), status=<Status.OK: ' '>, attachment_id=8, database='/home/employee.fdb', charset='ISO88591', protocol='TCPv4', address='192.168.1.5', user='SYSDBA', role='NONE', remote_process='/opt/firebird/bin/isql', remote_pid=8723)
406+
EventTransactionStart(event_id=2, timestamp=datetime.datetime(2014, 5, 23, 11, 0, 28, 616000), status=<Status.OK: ' '>, attachment_id=8, transaction_id=1568, options=['READ_COMMITTED', 'REC_VERSION', 'WAIT', 'READ_WRITE'])
407+
EventProcedureFinish(event_id=3, timestamp=datetime.datetime(2014, 5, 23, 11, 0, 30, 435000), status=<Status.OK: ' '>, attachment_id=8, transaction_id=1568, procedure='STP_READCONFIG', param_id=None, records=None, run_time=None, reads=None, writes=None, fetches=None, marks=None, access=None)
408+
"""
409+
_check_events(trace_lines, output)
410+
411+
def test_65_malformed_performance_single_value():
412+
"""Tests parsing with performance data containing a malformed single value.
413+
414+
This test verifies that the parser can handle performance lines where one of the
415+
comma-separated parts contains only a single word without a type suffix.
416+
"""
417+
trace_lines = """2014-05-23T11:00:28.5840 (3720:0000000000EFD9E8) ATTACH_DATABASE
418+
/home/employee.fdb (ATT_8, SYSDBA:NONE, ISO88591, TCPv4:192.168.1.5)
419+
/opt/firebird/bin/isql:8723
420+
421+
2014-05-23T11:00:28.6160 (3720:0000000000EFD9E8) START_TRANSACTION
422+
/home/employee.fdb (ATT_8, SYSDBA:NONE, ISO88591, TCPv4:192.168.1.5)
423+
/opt/firebird/bin/isql:8723
424+
(TRA_1568, READ_COMMITTED | REC_VERSION | WAIT | READ_WRITE)
425+
426+
2014-05-23T11:00:30.4350 (3720:0000000000EFD9E8) COMMIT_TRANSACTION
427+
/home/employee.fdb (ATT_8, SYSDBA:NONE, ISO88591, TCPv4:192.168.1.5)
428+
/opt/firebird/bin/isql:8723
429+
(TRA_1568, READ_COMMITTED | REC_VERSION | WAIT | READ_WRITE)
430+
5 ms, malformed, 10 read(s), 3 write(s)
431+
432+
"""
433+
# The performance line has "malformed" which is a single word without a type
434+
# The parser should skip this malformed value and parse the valid metrics
435+
output = """EventAttach(event_id=1, timestamp=datetime.datetime(2014, 5, 23, 11, 0, 28, 584000), status=<Status.OK: ' '>, attachment_id=8, database='/home/employee.fdb', charset='ISO88591', protocol='TCPv4', address='192.168.1.5', user='SYSDBA', role='NONE', remote_process='/opt/firebird/bin/isql', remote_pid=8723)
436+
EventTransactionStart(event_id=2, timestamp=datetime.datetime(2014, 5, 23, 11, 0, 28, 616000), status=<Status.OK: ' '>, attachment_id=8, transaction_id=1568, options=['READ_COMMITTED', 'REC_VERSION', 'WAIT', 'READ_WRITE'])
437+
EventCommit(event_id=3, timestamp=datetime.datetime(2014, 5, 23, 11, 0, 30, 435000), status=<Status.OK: ' '>, attachment_id=8, transaction_id=1568, options=['READ_COMMITTED', 'REC_VERSION', 'WAIT', 'READ_WRITE'], run_time=5, reads=10, writes=3, fetches=None, marks=None)
438+
"""
439+
_check_events(trace_lines, output)
440+
441+
def test_66_malformed_date():
442+
"""Tests parsing with malformed date parameter (double dash).
443+
444+
This test verifies the fix for date parsing errors where trace files contain
445+
malformed date values like '0000-01--26' (note the double dash).
446+
447+
The parser now handles strptime errors gracefully by storing the raw string value
448+
when date parsing fails.
449+
"""
450+
trace_lines = """2014-05-23T11:00:28.5840 (3720:0000000000EFD9E8) ATTACH_DATABASE
451+
/home/employee.fdb (ATT_8, SYSDBA:NONE, ISO88591, TCPv4:192.168.1.5)
452+
/opt/firebird/bin/isql:8723
453+
454+
2014-05-23T11:00:28.6160 (3720:0000000000EFD9E8) START_TRANSACTION
455+
/home/employee.fdb (ATT_8, SYSDBA:NONE, ISO88591, TCPv4:192.168.1.5)
456+
/opt/firebird/bin/isql:8723
457+
(TRA_1568, READ_COMMITTED | REC_VERSION | WAIT | READ_WRITE)
458+
459+
2014-05-23T11:00:30.4350 (3720:0000000000EFD9E8) EXECUTE_STATEMENT_FINISH
460+
/home/employee.fdb (ATT_8, SYSDBA:NONE, ISO88591, TCPv4:192.168.1.5)
461+
/opt/firebird/bin/isql:8723
462+
(TRA_1568, READ_COMMITTED | REC_VERSION | WAIT | READ_WRITE)
463+
464+
Statement 1:
465+
-------------------------------------------------------------------------------
466+
SELECT * FROM EMPLOYEE WHERE hire_date = ?
467+
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
468+
param0 = date, "0000-01--26"
469+
470+
0 records fetched
471+
15 ms, 147 read(s), 1 write(s), 6 fetch(es)
472+
473+
"""
474+
# The malformed date should be kept as a string instead of causing a parse error
475+
output = """EventAttach(event_id=1, timestamp=datetime.datetime(2014, 5, 23, 11, 0, 28, 584000), status=<Status.OK: ' '>, attachment_id=8, database='/home/employee.fdb', charset='ISO88591', protocol='TCPv4', address='192.168.1.5', user='SYSDBA', role='NONE', remote_process='/opt/firebird/bin/isql', remote_pid=8723)
476+
EventTransactionStart(event_id=2, timestamp=datetime.datetime(2014, 5, 23, 11, 0, 28, 616000), status=<Status.OK: ' '>, attachment_id=8, transaction_id=1568, options=['READ_COMMITTED', 'REC_VERSION', 'WAIT', 'READ_WRITE'])
477+
ParamSet(par_id=1, params=[('date', '0000-01--26')])
478+
SQLInfo(sql_id=1, sql='SELECT * FROM EMPLOYEE WHERE hire_date = ?', plan='')
479+
EventStatementFinish(event_id=3, timestamp=datetime.datetime(2014, 5, 23, 11, 0, 30, 435000), status=<Status.OK: ' '>, attachment_id=8, transaction_id=1568, statement_id=1, sql_id=1, param_id=1, records=0, run_time=15, reads=147, writes=1, fetches=6, marks=None, access=None)
480+
"""
481+
_check_events(trace_lines, output)
482+
483+
def test_67_unknown_performance_parameter():
484+
"""Tests parsing with unknown performance parameters.
485+
486+
This test verifies the fix for "Unhandled performance parameter" errors where
487+
trace files contain unknown or unexpected performance metric types.
488+
489+
Real-world example: Some traces contained "ROCK" as a performance parameter,
490+
likely due to data corruption or unusual Firebird versions.
491+
492+
The parser now skips unknown performance parameters instead of raising an error.
493+
"""
494+
trace_lines = """2014-05-23T11:00:28.5840 (3720:0000000000EFD9E8) ATTACH_DATABASE
495+
/home/employee.fdb (ATT_8, SYSDBA:NONE, ISO88591, TCPv4:192.168.1.5)
496+
/opt/firebird/bin/isql:8723
497+
498+
2014-05-23T11:00:28.6160 (3720:0000000000EFD9E8) START_TRANSACTION
499+
/home/employee.fdb (ATT_8, SYSDBA:NONE, ISO88591, TCPv4:192.168.1.5)
500+
/opt/firebird/bin/isql:8723
501+
(TRA_1568, READ_COMMITTED | REC_VERSION | WAIT | READ_WRITE)
502+
503+
2014-05-23T11:00:30.4350 (3720:0000000000EFD9E8) COMMIT_TRANSACTION
504+
/home/employee.fdb (ATT_8, SYSDBA:NONE, ISO88591, TCPv4:192.168.1.5)
505+
/opt/firebird/bin/isql:8723
506+
(TRA_1568, READ_COMMITTED | REC_VERSION | WAIT | READ_WRITE)
507+
5 ms, 10 read(s), 3 ROCK, 2 write(s)
508+
509+
"""
510+
# The unknown "ROCK" parameter should be skipped, and valid metrics should be parsed
511+
output = """EventAttach(event_id=1, timestamp=datetime.datetime(2014, 5, 23, 11, 0, 28, 584000), status=<Status.OK: ' '>, attachment_id=8, database='/home/employee.fdb', charset='ISO88591', protocol='TCPv4', address='192.168.1.5', user='SYSDBA', role='NONE', remote_process='/opt/firebird/bin/isql', remote_pid=8723)
512+
EventTransactionStart(event_id=2, timestamp=datetime.datetime(2014, 5, 23, 11, 0, 28, 616000), status=<Status.OK: ' '>, attachment_id=8, transaction_id=1568, options=['READ_COMMITTED', 'REC_VERSION', 'WAIT', 'READ_WRITE'])
513+
EventCommit(event_id=3, timestamp=datetime.datetime(2014, 5, 23, 11, 0, 30, 435000), status=<Status.OK: ' '>, attachment_id=8, transaction_id=1568, options=['READ_COMMITTED', 'REC_VERSION', 'WAIT', 'READ_WRITE'], run_time=5, reads=10, writes=2, fetches=None, marks=None)
514+
"""
515+
_check_events(trace_lines, output)

0 commit comments

Comments
 (0)