2026-01-08 02:57:12,507 - INFO - ya.test.2418559  - pytest_runtest_setup: ####################################################################################################
2026-01-08 02:57:12,507 - INFO - ya.test.2418559  - pytest_runtest_setup: test_excess_columns[json-additional_args4-row]
2026-01-08 02:57:12,507 - INFO - ya.test.2418559  - pytest_runtest_setup: ####################################################################################################
2026-01-08 02:57:12,507 - INFO - ya.test.2418559  - pytest_runtest_setup: Test setup
2026-01-08 02:57:12,509 - INFO - ya.test.2418559  - pytest_runtest_call: Test call (class_name: test_ydb_impex.py::TestImpex, test_name: test_excess_columns[json-additional_args4-row])
2026-01-08 02:57:12,509 - DEBUG - ydb.connection.2418559  - _prepare_call: RpcState(ExecuteSchemeQuery, 678f3a38-ca97-43cd-9a35-ecdb8108e038, ghrun-paw7opzmb4.auto.internal:31149): creating call state
2026-01-08 02:57:12,510 - DEBUG - ydb.connection.2418559  - _log_request: RpcState(ExecuteSchemeQuery, 678f3a38-ca97-43cd-9a35-ecdb8108e038, ghrun-paw7opzmb4.auto.internal:31149): request = { session_id: "ydb://session/3?node_id=1&id=NjEzYjI5MmUtYTZiMzIxMzctNmM2YWQ4ODItYWVlYzE5ODg=" yql_text: "\n        CREATE TABLE `/Root/test_excess_columns[json-additional_args4-row]` (\n            key Uint32 NOT NULL,\n            id Uint64,\n            value Utf8,\n            PRIMARY KEY(key)\n        )\n        \n        WITH (\n            STORE = row\n        )\n        " operation_params { operation_timeout { seconds: 600 } cancel_after { seconds: 600 } } }
2026-01-08 02:57:12,528 - DEBUG - ydb.connection.2418559  - _log_response: RpcState(ExecuteSchemeQuery, 678f3a38-ca97-43cd-9a35-ecdb8108e038, ghrun-paw7opzmb4.auto.internal:31149): response = { operation { ready: true status: SUCCESS } }
2026-01-08 02:57:12,528 - DEBUG - ya.test.2418559  - get_binary: Binary was found by /home/runner/.ya/build/build_root/pp6n/00339a/ydb/apps/ydb/ydb
2026-01-08 02:57:12,529 - DEBUG - ya.test.2418559  - _get_command_output_file: Command out will be placed to ydb.out.2
2026-01-08 02:57:12,529 - DEBUG - ya.test.2418559  - _get_command_output_file: Command err will be placed to ydb.err.5
2026-01-08 02:57:12,530 - DEBUG - ya.test.2418559  - execute: Executing '['/home/runner/.ya/build/build_root/pp6n/00339a/ydb/apps/ydb/ydb', '--endpoint', 'grpc://localhost:31149', '--database', '/Root', 'import', 'file', 'json', '-p', '/Root/test_excess_columns[json-additional_args4-row]', '-i', '/home/runner/.ya/build/build_root/pp6n/00339a/tmp/test_excess_columns_json_addit1/tempinput.json']' in 'None' (waiting)
2026-01-08 02:57:12,530 - DEBUG - ya.test.2418559  - execute: Command pid: 2426098
2026-01-08 02:57:12,641 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426098) rc: 0
2026-01-08 02:57:12,642 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426098) elapsed time (sec): 0.11031246185302734
2026-01-08 02:57:12,642 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426098) idrss: 0
2026-01-08 02:57:12,642 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426098) inblock: 0
2026-01-08 02:57:12,642 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426098) isrss: 0
2026-01-08 02:57:12,642 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426098) ixrss: 0
2026-01-08 02:57:12,642 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426098) majflt: 0
2026-01-08 02:57:12,642 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426098) maxrss: 187296
2026-01-08 02:57:12,642 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426098) minflt: 3947
2026-01-08 02:57:12,642 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426098) msgrcv: 0
2026-01-08 02:57:12,643 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426098) msgsnd: 0
2026-01-08 02:57:12,643 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426098) nivcsw: 2
2026-01-08 02:57:12,643 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426098) nsignals: 0
2026-01-08 02:57:12,643 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426098) nswap: 0
2026-01-08 02:57:12,643 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426098) nvcsw: 325
2026-01-08 02:57:12,643 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426098) oublock: 8
2026-01-08 02:57:12,643 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426098) stime: 0.028985
2026-01-08 02:57:12,643 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426098) utime: 0.032608
2026-01-08 02:57:12,643 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426098) wtime: 0.111
2026-01-08 02:57:12,644 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426098) output:

2026-01-08 02:57:12,644 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426098) errors:
Elapsed: 0.00287 sec. Total read size: 0B. Average processing speed: 0B/s.


2026-01-08 02:57:12,644 - DEBUG - __tests__.test_ydb_impex.2418559  - execute_ydb_cli_command: std_out:

2026-01-08 02:57:12,644 - DEBUG - ya.test.2418559  - get_binary: Binary was found by /home/runner/.ya/build/build_root/pp6n/00339a/ydb/apps/ydb/ydb
2026-01-08 02:57:12,645 - DEBUG - ya.test.2418559  - _get_command_output_file: Command err will be placed to ydb.err.6
2026-01-08 02:57:12,645 - DEBUG - ya.test.2418559  - execute: Executing '['/home/runner/.ya/build/build_root/pp6n/00339a/ydb/apps/ydb/ydb', '--endpoint', 'grpc://localhost:31149', '--database', '/Root', 'table', 'query', 'execute', '-q', 'SELECT `key`, `id`, `value` FROM `/Root/test_excess_columns[json-additional_args4-row]` ORDER BY `key`', '-t', 'scan', '--format', 'json-unicode']' in 'None' (waiting)
2026-01-08 02:57:12,646 - DEBUG - ya.test.2418559  - execute: Command pid: 2426412
2026-01-08 02:57:12,762 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426412) rc: 0
2026-01-08 02:57:12,762 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426412) elapsed time (sec): 0.11545634269714355
2026-01-08 02:57:12,762 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426412) idrss: 0
2026-01-08 02:57:12,762 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426412) inblock: 0
2026-01-08 02:57:12,762 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426412) isrss: 0
2026-01-08 02:57:12,762 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426412) ixrss: 0
2026-01-08 02:57:12,763 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426412) majflt: 0
2026-01-08 02:57:12,763 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426412) maxrss: 187296
2026-01-08 02:57:12,763 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426412) minflt: 3560
2026-01-08 02:57:12,763 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426412) msgrcv: 0
2026-01-08 02:57:12,763 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426412) msgsnd: 0
2026-01-08 02:57:12,763 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426412) nivcsw: 0
2026-01-08 02:57:12,763 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426412) nsignals: 0
2026-01-08 02:57:12,763 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426412) nswap: 0
2026-01-08 02:57:12,763 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426412) nvcsw: 181
2026-01-08 02:57:12,763 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426412) oublock: 8
2026-01-08 02:57:12,764 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426412) stime: 0.015571
2026-01-08 02:57:12,764 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426412) utime: 0.035035
2026-01-08 02:57:12,764 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426412) wtime: 0.116
2026-01-08 02:57:12,764 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426412) output:
{"key":1,"id":1111,"value":"one"}
{"key":2,"id":2222,"value":"two"}
{"key":3,"id":3333,"value":"three"}
{"key":5,"id":5555,"value":"five"}
{"key":7,"id":7777,"value":"seven"}

2026-01-08 02:57:12,764 - DEBUG - ya.test.2418559  - _save_outputs: Command (pid 2426412) errors:

2026-01-08 02:57:12,764 - DEBUG - __tests__.test_ydb_impex.2418559  - execute_ydb_cli_command: std_out:
{"key":1,"id":1111,"value":"one"}
{"key":2,"id":2222,"value":"two"}
{"key":3,"id":3333,"value":"three"}
{"key":5,"id":5555,"value":"five"}
{"key":7,"id":7777,"value":"seven"}

2026-01-08 02:57:12,765 - INFO - ya.test.2418559  - pytest_runtest_teardown: Test teardown
2026-01-08 02:57:34,767 - INFO - ydb.tests.library.harness.kikimr_runner.2418559  - stop: Stopped node localhost:31149/1
2026-01-08 02:57:34,768 - DEBUG - library.python.filelock.2418559  - release: Ensuring FileLock released: /home/runner/.ya/build/port_sync_dir/27266
2026-01-08 02:57:34,768 - DEBUG - library.python.filelock.2418559  - release: Ensuring FileLock released: /home/runner/.ya/build/port_sync_dir/28230
2026-01-08 02:57:34,768 - DEBUG - library.python.filelock.2418559  - release: Ensuring FileLock released: /home/runner/.ya/build/port_sync_dir/24037
2026-01-08 02:57:34,768 - DEBUG - library.python.filelock.2418559  - release: Ensuring FileLock released: /home/runner/.ya/build/port_sync_dir/31149
2026-01-08 02:57:34,768 - DEBUG - library.python.filelock.2418559  - release: Ensuring FileLock released: /home/runner/.ya/build/port_sync_dir/23972
2026-01-08 02:57:35,025 - DEBUG - ya.test - _verify_test: Verifying [test_ydb_impex.TestImpex.test_excess_columns[json-additional_args4-row] in ydb/tests/functional/ydb_cli] canonical results
2026-01-08 02:57:35,026 - DEBUG - ya.test - verify: Test test_ydb_impex.TestImpex.test_excess_columns[json-additional_args4-row] status: good
