2 @message |
assert
checked_mode: table, checked_DML upd, iter 0, number of added rows: 10
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: Records affected: 12
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: ID
checked_mode: table, checked_DML upd, iter 0, worker STDLOG:
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -1200
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -1100
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -1000
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -900
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -800
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -700
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -600
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -500
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -400
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -300
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 100
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 200
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: Records affected: 12
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: OLD_ID OP SNAP_NO_RANK
checked_mode: table, checked_DML upd, iter 0, worker STDLOG:
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 1
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 1
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 2
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 2
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 2
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 2
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 3
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 3
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 3
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 3
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 4
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 4
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 4
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 4
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 5
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 5
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 5
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 5
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 6
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 6
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 6
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 6
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 7
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 7
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 7
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 7
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 8
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 8
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 8
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 8
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 9
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 9
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 9
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 9
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 10
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 10
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 10
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 10
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 11
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 11
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 11
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 11
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -3 UPD 11
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -3UPD 11
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -4 UPD 11
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -4UPD 11
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -5 UPD 11
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -5UPD 11
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -6 UPD 11
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -6UPD 11
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -7 UPD 11
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -7UPD 11
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -8 UPD 11
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -8UPD 11
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -9 UPD 11
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -9UPD 11
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -10 UPD 11
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -10UPD 11
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -11 UPD 11
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -11UPD 11
- checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -12 UPD 11
+ checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -12UPD 11
checked_mode: table, checked_DML upd, iter 0, worker STDLOG: Records affected: 31
LOG DETAILS:
2025-07-01 06:04:46.616
2025-07-01 06:04:46.622 act = <firebird.qa.plugin.Action object at [hex]>
2025-07-01 06:04:46.628 fn_worker_sql = PosixPath('/var/tmp/qa_2024/test_12475/tmp_worker.sql')
2025-07-01 06:04:46.638 fn_worker_log = PosixPath('/var/tmp/qa_2024/test_12475/tmp_worker.log')
2025-07-01 06:04:46.645 fn_worker_err = PosixPath('/var/tmp/qa_2024/test_12475/tmp_worker.err')
2025-07-01 06:04:46.652 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-07-01 06:04:46.658
2025-07-01 06:04:46.663 @pytest.mark.trace
2025-07-01 06:04:46.667 @pytest.mark.version('>=4.0.2')
2025-07-01 06:04:46.672 def test_1(act: Action, fn_worker_sql: Path, fn_worker_log: Path, fn_worker_err: Path, capsys):
2025-07-01 06:04:46.678
2025-07-01 06:04:46.684 sql_init = (act.files_dir / 'read-consist-sttm-restart-DDL.sql').read_text()
2025-07-01 06:04:46.689
2025-07-01 06:04:46.696 for checked_mode in('table', 'view'):
2025-07-01 06:04:46.701 target_obj = 'test' if checked_mode == 'table' else 'v_test'
2025-07-01 06:04:46.706
2025-07-01 06:04:46.711 # NB: for 'lok' can not be used with a VIEW, error: "336397326 : WITH LOCK can be used only with a single physical table"
2025-07-01 06:04:46.716 for checked_DML in ('upd', 'mer', 'del', 'lok') if checked_mode == 'table' else ('upd', 'mer', 'del'):
2025-07-01 06:04:46.721
2025-07-01 06:04:46.726 ###################################################################################################################
2025-07-01 06:04:46.731 ### !!! NB !!! DO NOT SPLIT QUERIES ONTO MULTIPLE LINES OTHERWISE CHECK OF TRACE CONTENT WILL FAIL (SEE BELOW) ###
2025-07-01 06:04:46.736 ###################################################################################################################
2025-07-01 06:04:46.740 if checked_DML == 'upd':
2025-07-01 06:04:46.746 SQL_TO_BE_RESTARTED = f'update /* {SQL_TAG_THAT_WE_WAITING_FOR} */ {target_obj} set id = id * 100 where id <= 2 order by id DESC'
2025-07-01 06:04:46.752 elif checked_DML == 'mer':
2025-07-01 06:04:46.759 SQL_TO_BE_RESTARTED = f'merge /* {SQL_TAG_THAT_WE_WAITING_FOR} */ into {target_obj} t using (select x.id from {target_obj} x where x.id <= 2 order by id DESC) s on t.id = s.id when matched then update set t.id = s.id * 100'
2025-07-01 06:04:46.767 elif checked_DML == 'del':
2025-07-01 06:04:46.779 SQL_TO_BE_RESTARTED = f'delete /* {SQL_TAG_THAT_WE_WAITING_FOR} */ from {target_obj} where id <= 2 order by id DESC'
2025-07-01 06:04:46.789 elif checked_DML == 'lok':
2025-07-01 06:04:46.796 # ::: NB :::
2025-07-01 06:04:46.803 # We must SUPRESS sending record to client for SELECT WITH LOCK, otherwise error
2025-07-01 06:04:46.810 # deadlock/update conflist will raise immediately! Because of this, we enclose
2025-07-01 06:04:46.816 # such select into execute block which returns nothing:
2025-07-01 06:04:46.822 #
2025-07-01 06:04:46.831 SQL_TO_BE_RESTARTED = f'execute block /* {SQL_TAG_THAT_WE_WAITING_FOR} */ as declare c int; begin for select id from {target_obj} where id<=2 order by id DESC with lock into c do begin end end'
2025-07-01 06:04:46.840
2025-07-01 06:04:46.846 for main_iter in (0,1):
2025-07-01 06:04:46.852
2025-07-01 06:04:46.860 ###################################################################################
2025-07-01 06:04:46.867 ### H O W M A N Y R E S T A R T S W E W A N T T O C H E C K ###
2025-07-01 06:04:46.875 ###################################################################################
2025-07-01 06:04:46.882 ROWS_TO_ADD = 10 + 1 * main_iter
2025-07-01 06:04:46.889
2025-07-01 06:04:46.896 # Add either 12 or 14 rows, ID = 1,2, ..., 2+ROWS_TO_ADD:
2025-07-01 06:04:46.903 sql_addi = f'''
2025-07-01 06:04:46.910 set term ^;
2025-07-01 06:04:46.917 execute block as
2025-07-01 06:04:46.935 begin
2025-07-01 06:04:46.943 rdb$set_context('USER_SESSION', 'WHO', 'INIT_DATA');
2025-07-01 06:04:46.948 end
2025-07-01 06:04:46.953 ^
2025-07-01 06:04:46.959 set term ;^
2025-07-01 06:04:46.965 insert into {target_obj}(id, x) select row_number()over(),row_number()over() from rdb$types rows (2 + {ROWS_TO_ADD}); -- <<< INITIAL DATA
2025-07-01 06:04:46.971 commit;
2025-07-01 06:04:46.978 '''
2025-07-01 06:04:46.984
2025-07-01 06:04:46.990 act.isql(switches=['-q'], input = ''.join( (sql_init, sql_addi) ) )
2025-07-01 06:04:46.998 # ::: NOTE ::: We have to immediately quit if any error raised in prepare phase.
2025-07-01 06:04:47.007 # See also letter from dimitr, 01-feb-2022 14:46
2025-07-01 06:04:47.021 assert act.stderr == ''
2025-07-01 06:04:47.029 act.reset()
2025-07-01 06:04:47.036
2025-07-01 06:04:47.043 # Get Firebird log before test
2025-07-01 06:04:47.048 fb_log_init = act.get_firebird_log()
2025-07-01 06:04:47.054
2025-07-01 06:04:47.065 trace_cfg_items = [
2025-07-01 06:04:47.076 'time_threshold = 0',
2025-07-01 06:04:47.087 'log_errors = true',
2025-07-01 06:04:47.098 'log_statement_start = true',
2025-07-01 06:04:47.111 'log_statement_finish = true',
2025-07-01 06:04:47.125 ]
2025-07-01 06:04:47.137
2025-07-01 06:04:47.150 with act.trace(db_events = trace_cfg_items, encoding=locale.getpreferredencoding()):
2025-07-01 06:04:47.160
2025-07-01 06:04:47.169 with act.db.connect() as con_lock_1, act.db.connect() as con_lock_2, act.db.connect() as con_monitoring:
2025-07-01 06:04:47.175
2025-07-01 06:04:47.181 tpb_monitoring = tpb(isolation=Isolation.READ_COMMITTED_RECORD_VERSION, lock_timeout=0)
2025-07-01 06:04:47.186 tx_monitoring = con_monitoring.transaction_manager(tpb_monitoring)
2025-07-01 06:04:47.193 cur_monitoring = tx_monitoring.cursor()
2025-07-01 06:04:47.200
2025-07-01 06:04:47.207 locked_rows_map ={} # K = 0 or 1 (locker_1 and locker_2 respectively); V = ID of locked row
2025-07-01 06:04:47.214
2025-07-01 06:04:47.222 for i,c in enumerate((con_lock_1,con_lock_2)):
2025-07-01 06:04:47.229 sttm = f"execute block as begin rdb$set_context('USER_SESSION', 'WHO', 'LOCKER #{i+1}'); end"
2025-07-01 06:04:47.235 c.execute_immediate(sttm)
2025-07-01 06:04:47.240
2025-07-01 06:04:47.246 con_monitoring.execute_immediate("execute block as begin rdb$set_context('USER_SESSION', 'WHO', 'MONITOR'); end")
2025-07-01 06:04:47.251
2025-07-01 06:04:47.256 #########################
2025-07-01 06:04:47.261 ### L O C K E R - 1 ###
2025-07-01 06:04:47.266 #########################
2025-07-01 06:04:47.273 locked_rows_map[ 1 ] = 1
2025-07-01 06:04:47.280 con_lock_1.execute_immediate( f'update {target_obj} set id=id where id = {locked_rows_map[1]} /* locker-1 */' )
2025-07-01 06:04:47.286
2025-07-01 06:04:47.292 # Run UPDATE | DELETE | MERGE | SELECT WITH LOCK -- see {SQL_TO_BE_RESTARTED}
2025-07-01 06:04:47.298 # Every statement ends with 'ORDER BY ID DESC' and must hang because of lockes:
2025-07-01 06:04:47.303
2025-07-01 06:04:47.309 worker_sql = f'''
2025-07-01 06:04:47.314 set list on;
2025-07-01 06:04:47.324 set autoddl off;
2025-07-01 06:04:47.333 set term ^;
2025-07-01 06:04:47.339 execute block as
2025-07-01 06:04:47.346 begin
2025-07-01 06:04:47.355 rdb$set_context('USER_SESSION','WHO', 'WORKER');
2025-07-01 06:04:47.367 end
2025-07-01 06:04:47.376 ^
2025-07-01 06:04:47.384 set term ;^
2025-07-01 06:04:47.390 commit;
2025-07-01 06:04:47.398 SET KEEP_TRAN_PARAMS ON;
2025-07-01 06:04:47.407 set transaction read committed read consistency;
2025-07-01 06:04:47.417 set list off;
2025-07-01 06:04:47.424 set wng off;
2025-07-01 06:04:47.430
2025-07-01 06:04:47.436 set count on;
2025-07-01 06:04:47.442 set term ^;
2025-07-01 06:04:47.447 {SQL_TO_BE_RESTARTED}
2025-07-01 06:04:47.453 ^
2025-07-01 06:04:47.465 set term ;^
2025-07-01 06:04:47.474
2025-07-01 06:04:47.481 -- check results:
2025-07-01 06:04:47.487 -- ###############
2025-07-01 06:04:47.494 --set echo on;
2025-07-01 06:04:47.500 select id from {target_obj} order by id;
2025-07-01 06:04:47.506
2025-07-01 06:04:47.517 select v.old_id, v.op, v.snap_no_rank
2025-07-01 06:04:47.525 from v_worker_log v
2025-07-01 06:04:47.533 where v.op = iif( '{checked_DML}' = 'mer', 'upd', '{checked_DML}'); -- 'UPD' or 'DEL'; for 'SELECT WITH LOCK' no records will be in v_worker_log.
2025-07-01 06:04:47.539 --set echo off;
2025-07-01 06:04:47.544
2025-07-01 06:04:47.549 --set width who 10;
2025-07-01 06:04:47.555 -- DO NOT check this! Values can differ here from one run to another!
2025-07-01 06:04:47.566 -- select id, trn, who, old_id, new_id, op, rec_vers, global_cn, snap_no from tlog_done order by id;
2025-07-01 06:04:47.575 rollback;
2025-07-01 06:04:47.582
2025-07-01 06:04:47.589 '''
2025-07-01 06:04:47.595
2025-07-01 06:04:47.600 fn_worker_sql.write_text(worker_sql)
2025-07-01 06:04:47.606
2025-07-01 06:04:47.610 with fn_worker_log.open(mode='w') as hang_out, fn_worker_err.open(mode='w') as hang_err:
2025-07-01 06:04:47.618
2025-07-01 06:04:47.624 ############################################################################
2025-07-01 06:04:47.630 ### L A U N C H W O R K E R U S I N G I S Q L, A S Y N C. ###
2025-07-01 06:04:47.639 ############################################################################
2025-07-01 06:04:47.647 p_worker = subprocess.Popen([act.vars['isql'], '-i', str(fn_worker_sql),
2025-07-01 06:04:47.654 '-user', act.db.user,
2025-07-01 06:04:47.660 '-password', act.db.password,
2025-07-01 06:04:47.667 '-pag', '999999',
2025-07-01 06:04:47.678 act.db.dsn
2025-07-01 06:04:47.686 ],
2025-07-01 06:04:47.693 stdout = hang_out,
2025-07-01 06:04:47.701 stderr = hang_err
2025-07-01 06:04:47.710 )
2025-07-01 06:04:47.717
2025-07-01 06:04:47.722 # update ... set id = id * 100 where id <= 2 order by id DESC
2025-07-01 06:04:47.729
2025-07-01 06:04:47.735 # NB: when ISQL will establish attach, first record that it must lock is ID = 2 -- see above SQL_TO_BE_RESTARTED
2025-07-01 06:04:47.741 # We must to ensure that this (worker) attachment has been really created and LOCKS this record:
2025-07-01 06:04:47.746 #
2025-07-01 06:04:47.756 wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set /* monitor-ini */ id=id where id=2', SQL_TAG_THAT_WE_WAITING_FOR)
2025-07-01 06:04:47.770
2025-07-01 06:04:47.780 cur_lock_1 = con_lock_1.cursor()
2025-07-01 06:04:47.790 cur_lock_2 = con_lock_2.cursor()
2025-07-01 06:04:47.799 sttm = f'update {target_obj} set id = ? where abs( id ) = ?'
2025-07-01 06:04:47.808
2025-07-01 06:04:47.818 for i in range(0,ROWS_TO_ADD):
2025-07-01 06:04:47.827 v_id = 2 + ROWS_TO_ADD-i
2025-07-01 06:04:47.835 if i % 2 == 0:
2025-07-01 06:04:47.845 # main_iter = 0: ROWS_TO_ADD = 10 ==> v_id = 2+10-0 = 12, 2+10-2 = 10, 2+10-4 = 8, 6, 4, 2
2025-07-01 06:04:47.861 # main_iter = 1: ROWS_TO_ADD = 12 ==> v_id = 2+12-0 = 14, 2+10-2 = 12, 2+10-4 = 10, 8, 6, 4
2025-07-01 06:04:47.868 locked_rows_map[ i % 2 ] = -abs( v_id )
2025-07-01 06:04:47.874 cur_lock_2.execute( sttm + f"/* locker-2 lup, ini-upd, i = {i} */", ( -abs( v_id ), v_id, ) )
2025-07-01 06:04:47.879 con_lock_2.commit()
2025-07-01 06:04:47.885 cur_lock_2.execute( sttm + f"/* locker-2 lup, re-upd, i = {i} */", ( -abs( v_id ), v_id, ) )
2025-07-01 06:04:47.895 con_lock_1.commit() # releases ID = locked_rows_map[ 0 ]
2025-07-01 06:04:47.903 else:
2025-07-01 06:04:47.913 # main_iter = 0: ROWS_TO_ADD = 10 ==> v_id = 2+10-1 = 11, 2+10-3 = 9, 2+10-5 = 7, 5, 3, 1
2025-07-01 06:04:47.923 # main_iter = 1: ROWS_TO_ADD = 12 ==> v_id = 2+12-1 = 13, 2+10-3 = 11, 2+10-5 = 9, 7, 5, 3
2025-07-01 06:04:47.932 locked_rows_map[ i % 2 ] = -abs( v_id )
2025-07-01 06:04:47.938 cur_lock_1.execute( sttm + f"/* locker-1 lup, ini-upd, i = {i} */", ( -abs( v_id ), v_id, ) )
2025-07-01 06:04:47.944 con_lock_1.commit()
2025-07-01 06:04:47.951 cur_lock_1.execute( sttm + f"/* locker-1 lup, re-upd, i = {i} */", ( -abs( v_id ), v_id, ) )
2025-07-01 06:04:47.959 con_lock_2.commit() # releases ID = locked_rows_map[ 1 ]
2025-07-01 06:04:47.968
2025-07-01 06:04:47.976 # NB: when ISQL will establish attach, first record that it must lock is ID = 2 -- see above SQL_TO_BE_RESTARTED
2025-07-01 06:04:47.983 # We must to ensure that this (worker) attachment has been really created and LOCKS this record:
2025-07-01 06:04:47.989 #
2025-07-01 06:04:47.996 wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} /* monitor lup, i={i} */ set id=id where id = {locked_rows_map[ 1 - (i % 2) ]}', SQL_TAG_THAT_WE_WAITING_FOR)
2025-07-01 06:04:48.003
2025-07-01 06:04:48.009 cur_monitoring.execute(f'select count(*) from {target_obj}')
2025-07-01 06:04:48.015 for r in cur_monitoring:
2025-07-01 06:04:48.023 target_obj_cnt = r[0]
2025-07-01 06:04:48.034 #target_obj_cnt = cur_monitoring.fetchall()[0]
2025-07-01 06:04:48.043
2025-07-01 06:04:48.049 if ROWS_TO_ADD % 2 == 0:
2025-07-01 06:04:48.055 if con_lock_2.is_active():
2025-07-01 06:04:48.062 con_lock_2.commit()
2025-07-01 06:04:48.073 con_lock_1.commit()
2025-07-01 06:04:48.082 else:
2025-07-01 06:04:48.089 if con_lock_1.is_active():
2025-07-01 06:04:48.095 con_lock_1.commit()
2025-07-01 06:04:48.101 con_lock_2.commit()
2025-07-01 06:04:48.106
2025-07-01 06:04:48.112 # Here we wait for ISQL complete its mission:
2025-07-01 06:04:48.119 p_worker.wait()
2025-07-01 06:04:48.124
2025-07-01 06:04:48.135 #< with ... con_lock_1, ... con_lock_2
2025-07-01 06:04:48.144
2025-07-01 06:04:48.152
2025-07-01 06:04:48.160
2025-07-01 06:04:48.167 #####################################################
2025-07-01 06:04:48.174 ### check content of 'TEST' and 'TLOG*' tables ###
2025-07-01 06:04:48.180 #####################################################
2025-07-01 06:04:48.186
2025-07-01 06:04:48.192 print( f'checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = {main_iter}, number of added rows: {ROWS_TO_ADD}' )
2025-07-01 06:04:48.198
2025-07-01 06:04:48.204 for g in (fn_worker_log, fn_worker_err):
2025-07-01 06:04:48.210 logname = 'STDLOG' if g == fn_worker_log else 'STDERR'
2025-07-01 06:04:48.219 with g.open() as f:
2025-07-01 06:04:48.228 for line in f:
2025-07-01 06:04:48.236 if line.strip():
2025-07-01 06:04:48.241 print( f'checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = {main_iter}, worker {logname}: {line}' )
2025-07-01 06:04:48.247
2025-07-01 06:04:48.253 expected_stdout_worker = f"""
2025-07-01 06:04:48.261 """
2025-07-01 06:04:48.268 if main_iter == 0:
2025-07-01 06:04:48.274 if checked_DML in ('upd', 'mer'):
2025-07-01 06:04:48.280 expected_stdout_worker = f"""
2025-07-01 06:04:48.285 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, number of added rows: 10
2025-07-01 06:04:48.292 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: Records affected: 12
2025-07-01 06:04:48.299 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: ID
2025-07-01 06:04:48.306 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: =======
2025-07-01 06:04:48.315 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -1200
2025-07-01 06:04:48.326 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -1100
2025-07-01 06:04:48.336 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -1000
2025-07-01 06:04:48.344 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -900
2025-07-01 06:04:48.352 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -800
2025-07-01 06:04:48.360 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -700
2025-07-01 06:04:48.368 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -600
2025-07-01 06:04:48.375 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -500
2025-07-01 06:04:48.383 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -400
2025-07-01 06:04:48.390 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -300
2025-07-01 06:04:48.400 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 100
2025-07-01 06:04:48.411 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 200
2025-07-01 06:04:48.419 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: Records affected: 12
2025-07-01 06:04:48.428 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-01 06:04:48.434 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: ======= ====== =====================
2025-07-01 06:04:48.440 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 1
2025-07-01 06:04:48.447 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 2
2025-07-01 06:04:48.453 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 2
2025-07-01 06:04:48.460 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 3
2025-07-01 06:04:48.471 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 3
2025-07-01 06:04:48.481 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 4
2025-07-01 06:04:48.488 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 4
2025-07-01 06:04:48.494 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 5
2025-07-01 06:04:48.501 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 5
2025-07-01 06:04:48.512 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 6
2025-07-01 06:04:48.521 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 6
2025-07-01 06:04:48.528 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 7
2025-07-01 06:04:48.535 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 7
2025-07-01 06:04:48.541 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 8
2025-07-01 06:04:48.547 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 8
2025-07-01 06:04:48.553 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 9
2025-07-01 06:04:48.559 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 9
2025-07-01 06:04:48.565 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 10
2025-07-01 06:04:48.571 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 10
2025-07-01 06:04:48.578 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 11
2025-07-01 06:04:48.583 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 11
2025-07-01 06:04:48.589 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -3 UPD 11
2025-07-01 06:04:48.595 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -4 UPD 11
2025-07-01 06:04:48.602 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -5 UPD 11
2025-07-01 06:04:48.608 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -6 UPD 11
2025-07-01 06:04:48.614 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -7 UPD 11
2025-07-01 06:04:48.620 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -8 UPD 11
2025-07-01 06:04:48.626 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -9 UPD 11
2025-07-01 06:04:48.632 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -10 UPD 11
2025-07-01 06:04:48.638 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -11 UPD 11
2025-07-01 06:04:48.643 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -12 UPD 11
2025-07-01 06:04:48.649 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: Records affected: 31
2025-07-01 06:04:48.655 """
2025-07-01 06:04:48.663 elif checked_DML == 'lok':
2025-07-01 06:04:48.668 expected_stdout_worker = f"""
2025-07-01 06:04:48.674 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, number of added rows: 10
2025-07-01 06:04:48.680 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: ID
2025-07-01 06:04:48.686 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: =======
2025-07-01 06:04:48.692 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -12
2025-07-01 06:04:48.698 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -11
2025-07-01 06:04:48.704 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -10
2025-07-01 06:04:48.710 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -9
2025-07-01 06:04:48.716 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -8
2025-07-01 06:04:48.722 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -7
2025-07-01 06:04:48.728 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -6
2025-07-01 06:04:48.734 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -5
2025-07-01 06:04:48.740 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -4
2025-07-01 06:04:48.746 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -3
2025-07-01 06:04:48.752 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1
2025-07-01 06:04:48.758 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2
2025-07-01 06:04:48.764 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: Records affected: 12
2025-07-01 06:04:48.770 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: Records affected: 0
2025-07-01 06:04:48.776 """
2025-07-01 06:04:48.781 elif checked_DML == 'del':
2025-07-01 06:04:48.787 expected_stdout_worker = f"""
2025-07-01 06:04:48.793 checked_mode: {checked_mode}, checked_DML = del, iter = 0, number of added rows: 10
2025-07-01 06:04:48.799 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: Records affected: 12
2025-07-01 06:04:48.806 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: Records affected: 0
2025-07-01 06:04:48.816 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-01 06:04:48.827 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: ======= ====== =====================
2025-07-01 06:04:48.835 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 1
2025-07-01 06:04:48.842 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 2
2025-07-01 06:04:48.848 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 2
2025-07-01 06:04:48.853 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 3
2025-07-01 06:04:48.859 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 3
2025-07-01 06:04:48.867 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 4
2025-07-01 06:04:48.879 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 4
2025-07-01 06:04:48.886 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 5
2025-07-01 06:04:48.892 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 5
2025-07-01 06:04:48.900 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 6
2025-07-01 06:04:48.908 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 6
2025-07-01 06:04:48.916 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 7
2025-07-01 06:04:48.923 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 7
2025-07-01 06:04:48.930 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 8
2025-07-01 06:04:48.939 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 8
2025-07-01 06:04:48.949 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 9
2025-07-01 06:04:48.957 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 9
2025-07-01 06:04:48.964 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 10
2025-07-01 06:04:48.970 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 10
2025-07-01 06:04:48.975 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 11
2025-07-01 06:04:48.984 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 11
2025-07-01 06:04:48.993 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -3 DEL 11
2025-07-01 06:04:49.001 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -4 DEL 11
2025-07-01 06:04:49.013 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -5 DEL 11
2025-07-01 06:04:49.023 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -6 DEL 11
2025-07-01 06:04:49.031 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -7 DEL 11
2025-07-01 06:04:49.039 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -8 DEL 11
2025-07-01 06:04:49.048 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -9 DEL 11
2025-07-01 06:04:49.059 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -10 DEL 11
2025-07-01 06:04:49.068 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -11 DEL 11
2025-07-01 06:04:49.075 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -12 DEL 11
2025-07-01 06:04:49.082 checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: Records affected: 31
2025-07-01 06:04:49.087 """
2025-07-01 06:04:49.095 else:
2025-07-01 06:04:49.107 if checked_DML in ('upd', 'mer'):
2025-07-01 06:04:49.115 expected_stdout_worker = f"""
2025-07-01 06:04:49.123 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, number of added rows: 11
2025-07-01 06:04:49.131 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: Records affected: 2
2025-07-01 06:04:49.141 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: ID
2025-07-01 06:04:49.150 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: =======
2025-07-01 06:04:49.157 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -13
2025-07-01 06:04:49.169 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -12
2025-07-01 06:04:49.180 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -11
2025-07-01 06:04:49.190 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -10
2025-07-01 06:04:49.199 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -9
2025-07-01 06:04:49.210 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -8
2025-07-01 06:04:49.219 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -7
2025-07-01 06:04:49.227 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -6
2025-07-01 06:04:49.238 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -5
2025-07-01 06:04:49.245 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -4
2025-07-01 06:04:49.253 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -3
2025-07-01 06:04:49.260 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1
2025-07-01 06:04:49.267 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2
2025-07-01 06:04:49.274 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: Records affected: 13
2025-07-01 06:04:49.283 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-01 06:04:49.296 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: ======= ====== =====================
2025-07-01 06:04:49.305 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 1
2025-07-01 06:04:49.316 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 2
2025-07-01 06:04:49.322 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 2
2025-07-01 06:04:49.330 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 3
2025-07-01 06:04:49.340 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 3
2025-07-01 06:04:49.348 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 4
2025-07-01 06:04:49.356 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 4
2025-07-01 06:04:49.364 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 5
2025-07-01 06:04:49.377 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 5
2025-07-01 06:04:49.389 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 6
2025-07-01 06:04:49.397 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 6
2025-07-01 06:04:49.404 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 7
2025-07-01 06:04:49.411 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 7
2025-07-01 06:04:49.419 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 8
2025-07-01 06:04:49.427 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 8
2025-07-01 06:04:49.435 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 9
2025-07-01 06:04:49.444 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 9
2025-07-01 06:04:49.453 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 10
2025-07-01 06:04:49.459 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 10
2025-07-01 06:04:49.466 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 11
2025-07-01 06:04:49.472 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 11
2025-07-01 06:04:49.478 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: Records affected: 21
2025-07-01 06:04:49.484 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: Statement failed, SQLSTATE = 40001
2025-07-01 06:04:49.494 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: deadlock
2025-07-01 06:04:49.505 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: -update conflicts with concurrent update
2025-07-01 06:04:49.516 concurrent transaction number is
2025-07-01 06:04:49.523 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR:
2025-07-01 06:04:49.529 """
2025-07-01 06:04:49.534 elif checked_DML == 'lok':
2025-07-01 06:04:49.539 expected_stdout_worker = f"""
2025-07-01 06:04:49.543 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, number of added rows: 11
2025-07-01 06:04:49.548 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: ID
2025-07-01 06:04:49.552 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: =======
2025-07-01 06:04:49.558 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -13
2025-07-01 06:04:49.566 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -12
2025-07-01 06:04:49.576 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -11
2025-07-01 06:04:49.588 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -10
2025-07-01 06:04:49.600 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -9
2025-07-01 06:04:49.609 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -8
2025-07-01 06:04:49.616 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -7
2025-07-01 06:04:49.622 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -6
2025-07-01 06:04:49.628 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -5
2025-07-01 06:04:49.635 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -4
2025-07-01 06:04:49.641 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -3
2025-07-01 06:04:49.650 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1
2025-07-01 06:04:49.662 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2
2025-07-01 06:04:49.671 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: Records affected: 13
2025-07-01 06:04:49.680 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: Records affected: 0
2025-07-01 06:04:49.692 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: Statement failed, SQLSTATE = 40001
2025-07-01 06:04:49.704 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: deadlock
2025-07-01 06:04:49.713 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: -update conflicts with concurrent update
2025-07-01 06:04:49.719 concurrent transaction number is
2025-07-01 06:04:49.729 checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR:
2025-07-01 06:04:49.737 """
2025-07-01 06:04:49.744 elif checked_DML == 'del':
2025-07-01 06:04:49.756 expected_stdout_worker = f"""
2025-07-01 06:04:49.764 checked_mode: {checked_mode}, checked_DML = del, iter = 1, number of added rows: 11
2025-07-01 06:04:49.773 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: Records affected: 2
2025-07-01 06:04:49.784 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: ID
2025-07-01 06:04:49.796 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: =======
2025-07-01 06:04:49.805 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -13
2025-07-01 06:04:49.812 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -12
2025-07-01 06:04:49.819 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -11
2025-07-01 06:04:49.827 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -10
2025-07-01 06:04:49.838 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -9
2025-07-01 06:04:49.850 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -8
2025-07-01 06:04:49.857 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -7
2025-07-01 06:04:49.863 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -6
2025-07-01 06:04:49.870 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -5
2025-07-01 06:04:49.878 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -4
2025-07-01 06:04:49.887 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -3
2025-07-01 06:04:49.898 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1
2025-07-01 06:04:49.905 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2
2025-07-01 06:04:49.912 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: Records affected: 13
2025-07-01 06:04:49.919 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-01 06:04:49.927 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: ======= ====== =====================
2025-07-01 06:04:49.934 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 1
2025-07-01 06:04:49.943 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 2
2025-07-01 06:04:49.957 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 2
2025-07-01 06:04:49.968 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 3
2025-07-01 06:04:49.977 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 3
2025-07-01 06:04:49.984 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 4
2025-07-01 06:04:49.991 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 4
2025-07-01 06:04:49.999 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 5
2025-07-01 06:04:50.011 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 5
2025-07-01 06:04:50.020 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 6
2025-07-01 06:04:50.034 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 6
2025-07-01 06:04:50.045 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 7
2025-07-01 06:04:50.055 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 7
2025-07-01 06:04:50.065 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 8
2025-07-01 06:04:50.072 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 8
2025-07-01 06:04:50.084 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 9
2025-07-01 06:04:50.094 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 9
2025-07-01 06:04:50.105 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 10
2025-07-01 06:04:50.120 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 10
2025-07-01 06:04:50.131 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 11
2025-07-01 06:04:50.139 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 11
2025-07-01 06:04:50.146 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: Records affected: 21
2025-07-01 06:04:50.155 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDERR: Statement failed, SQLSTATE = 40001
2025-07-01 06:04:50.167 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDERR: deadlock
2025-07-01 06:04:50.176 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDERR: -update conflicts with concurrent update
2025-07-01 06:04:50.184 concurrent transaction number is
2025-07-01 06:04:50.191 checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDERR:
2025-07-01 06:04:50.199 """
2025-07-01 06:04:50.205
2025-07-01 06:04:50.211 act.expected_stdout = expected_stdout_worker
2025-07-01 06:04:50.216 act.stdout = capsys.readouterr().out
2025-07-01 06:04:50.222 > assert act.clean_stdout == act.clean_expected_stdout
2025-07-01 06:04:50.228 E assert
2025-07-01 06:04:50.234 E checked_mode: table, checked_DML upd, iter 0, number of added rows: 10
2025-07-01 06:04:50.241 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: Records affected: 12
2025-07-01 06:04:50.248 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: ID
2025-07-01 06:04:50.256 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG:
2025-07-01 06:04:50.263 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -1200
2025-07-01 06:04:50.271 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -1100
2025-07-01 06:04:50.282 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -1000
2025-07-01 06:04:50.295 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -900
2025-07-01 06:04:50.306 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -800
2025-07-01 06:04:50.318 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -700
2025-07-01 06:04:50.329 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -600
2025-07-01 06:04:50.340 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -500
2025-07-01 06:04:50.349 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -400
2025-07-01 06:04:50.360 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -300
2025-07-01 06:04:50.374 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 100
2025-07-01 06:04:50.384 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 200
2025-07-01 06:04:50.394 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: Records affected: 12
2025-07-01 06:04:50.402 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: OLD_ID OP SNAP_NO_RANK
2025-07-01 06:04:50.410 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG:
2025-07-01 06:04:50.421 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 1
2025-07-01 06:04:50.435 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 1
2025-07-01 06:04:50.443 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 2
2025-07-01 06:04:50.468 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 2
2025-07-01 06:04:50.478 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 2
2025-07-01 06:04:50.492 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 2
2025-07-01 06:04:50.498 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 3
2025-07-01 06:04:50.508 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 3
2025-07-01 06:04:50.514 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 3
2025-07-01 06:04:50.525 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 3
2025-07-01 06:04:50.531 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 4
2025-07-01 06:04:50.546 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 4
2025-07-01 06:04:50.553 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 4
2025-07-01 06:04:50.565 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 4
2025-07-01 06:04:50.570 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 5
2025-07-01 06:04:50.591 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 5
2025-07-01 06:04:50.599 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 5
2025-07-01 06:04:50.618 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 5
2025-07-01 06:04:50.627 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 6
2025-07-01 06:04:50.641 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 6
2025-07-01 06:04:50.647 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 6
2025-07-01 06:04:50.657 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 6
2025-07-01 06:04:50.662 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 7
2025-07-01 06:04:50.674 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 7
2025-07-01 06:04:50.680 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 7
2025-07-01 06:04:50.692 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 7
2025-07-01 06:04:50.697 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 8
2025-07-01 06:04:50.710 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 8
2025-07-01 06:04:50.716 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 8
2025-07-01 06:04:50.728 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 8
2025-07-01 06:04:50.734 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 9
2025-07-01 06:04:50.746 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 9
2025-07-01 06:04:50.751 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 9
2025-07-01 06:04:50.762 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 9
2025-07-01 06:04:50.768 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 10
2025-07-01 06:04:50.780 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 10
2025-07-01 06:04:50.787 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 10
2025-07-01 06:04:50.807 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 10
2025-07-01 06:04:50.814 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 11
2025-07-01 06:04:50.827 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 11
2025-07-01 06:04:50.833 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 11
2025-07-01 06:04:50.846 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 11
2025-07-01 06:04:50.854 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -3 UPD 11
2025-07-01 06:04:50.876 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -3UPD 11
2025-07-01 06:04:50.883 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -4 UPD 11
2025-07-01 06:04:50.901 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -4UPD 11
2025-07-01 06:04:50.909 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -5 UPD 11
2025-07-01 06:04:50.923 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -5UPD 11
2025-07-01 06:04:50.930 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -6 UPD 11
2025-07-01 06:04:50.946 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -6UPD 11
2025-07-01 06:04:50.956 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -7 UPD 11
2025-07-01 06:04:50.968 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -7UPD 11
2025-07-01 06:04:50.973 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -8 UPD 11
2025-07-01 06:04:50.984 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -8UPD 11
2025-07-01 06:04:50.988 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -9 UPD 11
2025-07-01 06:04:50.997 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -9UPD 11
2025-07-01 06:04:51.002 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -10 UPD 11
2025-07-01 06:04:51.011 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -10UPD 11
2025-07-01 06:04:51.016 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -11 UPD 11
2025-07-01 06:04:51.030 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -11UPD 11
2025-07-01 06:04:51.037 E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -12 UPD 11
2025-07-01 06:04:51.054 E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -12UPD 11
2025-07-01 06:04:51.062 E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: Records affected: 31
2025-07-01 06:04:51.069
2025-07-01 06:04:51.075 tests/functional/transactions/test_read_consist_sttm_restart_max_limit.py:631: AssertionError
2025-07-01 06:04:51.082 ---------------------------- Captured stdout setup -----------------------------
2025-07-01 06:04:51.091 Creating db: localhost:/var/tmp/qa_2024/test_12475/test.fdb [page_size=None, sql_dialect=None, charset='NONE', user=SYSDBA, password=masterkey]
|
3 #text |
act = <firebird.qa.plugin.Action pytest object at [hex]>
fn_worker_sql = PosixPath('/var/tmp/qa_2024/test_12475/tmp_worker.sql')
fn_worker_log = PosixPath('/var/tmp/qa_2024/test_12475/tmp_worker.log')
fn_worker_err = PosixPath('/var/tmp/qa_2024/test_12475/tmp_worker.err')
capsys = <_pytest.capture.CaptureFixture pytest object at [hex]>
@pytest.mark.trace
@pytest.mark.version('>=4.0.2')
def test_1(act: Action, fn_worker_sql: Path, fn_worker_log: Path, fn_worker_err: Path, capsys):
sql_init = (act.files_dir / 'read-consist-sttm-restart-DDL.sql').read_text()
for checked_mode in('table', 'view'):
target_obj = 'test' if checked_mode == 'table' else 'v_test'
# NB: for 'lok' can not be used with a VIEW, error: "336397326 : WITH LOCK can be used only with a single physical table"
for checked_DML in ('upd', 'mer', 'del', 'lok') if checked_mode == 'table' else ('upd', 'mer', 'del'):
###################################################################################################################
### !!! NB !!! DO NOT SPLIT QUERIES ONTO MULTIPLE LINES OTHERWISE CHECK OF TRACE CONTENT WILL FAIL (SEE BELOW) ###
###################################################################################################################
if checked_DML == 'upd':
SQL_TO_BE_RESTARTED = f'update /* {SQL_TAG_THAT_WE_WAITING_FOR} */ {target_obj} set id = id * 100 where id <= 2 order by id DESC'
elif checked_DML == 'mer':
SQL_TO_BE_RESTARTED = f'merge /* {SQL_TAG_THAT_WE_WAITING_FOR} */ into {target_obj} t using (select x.id from {target_obj} x where x.id <= 2 order by id DESC) s on t.id = s.id when matched then update set t.id = s.id * 100'
elif checked_DML == 'del':
SQL_TO_BE_RESTARTED = f'delete /* {SQL_TAG_THAT_WE_WAITING_FOR} */ from {target_obj} where id <= 2 order by id DESC'
elif checked_DML == 'lok':
# ::: NB :::
# We must SUPRESS sending record to client for SELECT WITH LOCK, otherwise error
# deadlock/update conflist will raise immediately! Because of this, we enclose
# such select into execute block which returns nothing:
#
SQL_TO_BE_RESTARTED = f'execute block /* {SQL_TAG_THAT_WE_WAITING_FOR} */ as declare c int; begin for select id from {target_obj} where id<=2 order by id DESC with lock into c do begin end end'
for main_iter in (0,1):
###################################################################################
### H O W M A N Y R E S T A R T S W E W A N T T O C H E C K ###
###################################################################################
ROWS_TO_ADD = 10 + 1 * main_iter
# Add either 12 or 14 rows, ID = 1,2, ..., 2+ROWS_TO_ADD:
sql_addi = f'''
set term ^;
execute block as
begin
rdb$set_context('USER_SESSION', 'WHO', 'INIT_DATA');
end
^
set term ;^
insert into {target_obj}(id, x) select row_number()over(),row_number()over() from rdb$types rows (2 + {ROWS_TO_ADD}); -- <<< INITIAL DATA
commit;
'''
act.isql(switches=['-q'], input = ''.join( (sql_init, sql_addi) ) )
# ::: NOTE ::: We have to immediately quit if any error raised in prepare phase.
# See also letter from dimitr, 01-feb-2022 14:46
assert act.stderr == ''
act.reset()
# Get Firebird log before test
fb_log_init = act.get_firebird_log()
trace_cfg_items = [
'time_threshold = 0',
'log_errors = true',
'log_statement_start = true',
'log_statement_finish = true',
]
with act.trace(db_events = trace_cfg_items, encoding=locale.getpreferredencoding()):
with act.db.connect() as con_lock_1, act.db.connect() as con_lock_2, act.db.connect() as con_monitoring:
tpb_monitoring = tpb(isolation=Isolation.READ_COMMITTED_RECORD_VERSION, lock_timeout=0)
tx_monitoring = con_monitoring.transaction_manager(tpb_monitoring)
cur_monitoring = tx_monitoring.cursor()
locked_rows_map ={} # K = 0 or 1 (locker_1 and locker_2 respectively); V = ID of locked row
for i,c in enumerate((con_lock_1,con_lock_2)):
sttm = f"execute block as begin rdb$set_context('USER_SESSION', 'WHO', 'LOCKER #{i+1}'); end"
c.execute_immediate(sttm)
con_monitoring.execute_immediate("execute block as begin rdb$set_context('USER_SESSION', 'WHO', 'MONITOR'); end")
#########################
### L O C K E R - 1 ###
#########################
locked_rows_map[ 1 ] = 1
con_lock_1.execute_immediate( f'update {target_obj} set id=id where id = {locked_rows_map[1]} /* locker-1 */' )
# Run UPDATE | DELETE | MERGE | SELECT WITH LOCK -- see {SQL_TO_BE_RESTARTED}
# Every statement ends with 'ORDER BY ID DESC' and must hang because of lockes:
worker_sql = f'''
set list on;
set autoddl off;
set term ^;
execute block as
begin
rdb$set_context('USER_SESSION','WHO', 'WORKER');
end
^
set term ;^
commit;
SET KEEP_TRAN_PARAMS ON;
set transaction read committed read consistency;
set list off;
set wng off;
set count on;
set term ^;
{SQL_TO_BE_RESTARTED}
^
set term ;^
-- check results:
-- ###############
--set echo on;
select id from {target_obj} order by id;
select v.old_id, v.op, v.snap_no_rank
from v_worker_log v
where v.op = iif( '{checked_DML}' = 'mer', 'upd', '{checked_DML}'); -- 'UPD' or 'DEL'; for 'SELECT WITH LOCK' no records will be in v_worker_log.
--set echo off;
--set width who 10;
-- DO NOT check this! Values can differ here from one run to another!
-- select id, trn, who, old_id, new_id, op, rec_vers, global_cn, snap_no from tlog_done order by id;
rollback;
'''
fn_worker_sql.write_text(worker_sql)
with fn_worker_log.open(mode='w') as hang_out, fn_worker_err.open(mode='w') as hang_err:
############################################################################
### L A U N C H W O R K E R U S I N G I S Q L, A S Y N C. ###
############################################################################
p_worker = subprocess.Popen([act.vars['isql'], '-i', str(fn_worker_sql),
'-user', act.db.user,
'-password', act.db.password,
'-pag', '999999',
act.db.dsn
],
stdout = hang_out,
stderr = hang_err
)
# update ... set id = id * 100 where id <= 2 order by id DESC
# NB: when ISQL will establish attach, first record that it must lock is ID = 2 -- see above SQL_TO_BE_RESTARTED
# We must to ensure that this (worker) attachment has been really created and LOCKS this record:
#
wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} set /* monitor-ini */ id=id where id=2', SQL_TAG_THAT_WE_WAITING_FOR)
cur_lock_1 = con_lock_1.cursor()
cur_lock_2 = con_lock_2.cursor()
sttm = f'update {target_obj} set id = ? where abs( id ) = ?'
for i in range(0,ROWS_TO_ADD):
v_id = 2 + ROWS_TO_ADD-i
if i % 2 == 0:
# main_iter = 0: ROWS_TO_ADD = 10 ==> v_id = 2+10-0 = 12, 2+10-2 = 10, 2+10-4 = 8, 6, 4, 2
# main_iter = 1: ROWS_TO_ADD = 12 ==> v_id = 2+12-0 = 14, 2+10-2 = 12, 2+10-4 = 10, 8, 6, 4
locked_rows_map[ i % 2 ] = -abs( v_id )
cur_lock_2.execute( sttm + f"/* locker-2 lup, ini-upd, i = {i} */", ( -abs( v_id ), v_id, ) )
con_lock_2.commit()
cur_lock_2.execute( sttm + f"/* locker-2 lup, re-upd, i = {i} */", ( -abs( v_id ), v_id, ) )
con_lock_1.commit() # releases ID = locked_rows_map[ 0 ]
else:
# main_iter = 0: ROWS_TO_ADD = 10 ==> v_id = 2+10-1 = 11, 2+10-3 = 9, 2+10-5 = 7, 5, 3, 1
# main_iter = 1: ROWS_TO_ADD = 12 ==> v_id = 2+12-1 = 13, 2+10-3 = 11, 2+10-5 = 9, 7, 5, 3
locked_rows_map[ i % 2 ] = -abs( v_id )
cur_lock_1.execute( sttm + f"/* locker-1 lup, ini-upd, i = {i} */", ( -abs( v_id ), v_id, ) )
con_lock_1.commit()
cur_lock_1.execute( sttm + f"/* locker-1 lup, re-upd, i = {i} */", ( -abs( v_id ), v_id, ) )
con_lock_2.commit() # releases ID = locked_rows_map[ 1 ]
# NB: when ISQL will establish attach, first record that it must lock is ID = 2 -- see above SQL_TO_BE_RESTARTED
# We must to ensure that this (worker) attachment has been really created and LOCKS this record:
#
wait_for_record_become_locked(tx_monitoring, cur_monitoring, f'update {target_obj} /* monitor lup, i={i} */ set id=id where id = {locked_rows_map[ 1 - (i % 2) ]}', SQL_TAG_THAT_WE_WAITING_FOR)
cur_monitoring.execute(f'select count(*) from {target_obj}')
for r in cur_monitoring:
target_obj_cnt = r[0]
#target_obj_cnt = cur_monitoring.fetchall()[0]
if ROWS_TO_ADD % 2 == 0:
if con_lock_2.is_active():
con_lock_2.commit()
con_lock_1.commit()
else:
if con_lock_1.is_active():
con_lock_1.commit()
con_lock_2.commit()
# Here we wait for ISQL complete its mission:
p_worker.wait()
#< with ... con_lock_1, ... con_lock_2
#####################################################
### check content of 'TEST' and 'TLOG*' tables ###
#####################################################
print( f'checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = {main_iter}, number of added rows: {ROWS_TO_ADD}' )
for g in (fn_worker_log, fn_worker_err):
logname = 'STDLOG' if g == fn_worker_log else 'STDERR'
with g.open() as f:
for line in f:
if line.strip():
print( f'checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = {main_iter}, worker {logname}: {line}' )
expected_stdout_worker = f"""
"""
if main_iter == 0:
if checked_DML in ('upd', 'mer'):
expected_stdout_worker = f"""
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, number of added rows: 10
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: Records affected: 12
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: ID
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: =======
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -1200
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -1100
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -1000
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -900
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -800
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -700
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -600
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -500
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -400
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -300
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 100
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 200
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: Records affected: 12
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: OLD_ID OP SNAP_NO_RANK
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: ======= ====== =====================
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 1
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 2
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 2
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 3
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 3
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 4
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 4
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 5
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 5
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 6
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 6
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 7
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 7
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 8
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 8
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 9
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 9
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 10
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 10
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -3 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -4 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -5 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -6 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -7 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -8 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -9 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -10 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -11 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -12 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: Records affected: 31
"""
elif checked_DML == 'lok':
expected_stdout_worker = f"""
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, number of added rows: 10
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: ID
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: =======
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -12
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -10
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -9
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -8
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -7
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -6
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -5
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -4
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: -3
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 1
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: 2
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: Records affected: 12
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 0, worker STDLOG: Records affected: 0
"""
elif checked_DML == 'del':
expected_stdout_worker = f"""
checked_mode: {checked_mode}, checked_DML = del, iter = 0, number of added rows: 10
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: Records affected: 12
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: Records affected: 0
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: OLD_ID OP SNAP_NO_RANK
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: ======= ====== =====================
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 1
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 2
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 2
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 3
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 3
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 4
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 4
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 5
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 5
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 6
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 6
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 7
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 7
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 8
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 8
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 9
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 9
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 10
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 10
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 2 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: 1 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -3 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -4 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -5 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -6 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -7 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -8 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -9 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -10 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -11 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: -12 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 0, worker STDLOG: Records affected: 31
"""
else:
if checked_DML in ('upd', 'mer'):
expected_stdout_worker = f"""
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, number of added rows: 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: Records affected: 2
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: ID
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: =======
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -13
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -12
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -10
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -9
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -8
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -7
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -6
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -5
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -4
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -3
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: Records affected: 13
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: OLD_ID OP SNAP_NO_RANK
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: ======= ====== =====================
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 1
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 2
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 2
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 3
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 3
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 4
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 4
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 5
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 5
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 6
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 6
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 7
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 7
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 8
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 8
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 9
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 9
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 10
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 10
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1 UPD 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: Records affected: 21
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: Statement failed, SQLSTATE = 40001
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: deadlock
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: -update conflicts with concurrent update
concurrent transaction number is
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR:
"""
elif checked_DML == 'lok':
expected_stdout_worker = f"""
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, number of added rows: 11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: ID
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: =======
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -13
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -12
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -11
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -10
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -9
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -8
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -7
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -6
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -5
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -4
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: -3
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 1
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: 2
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: Records affected: 13
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDLOG: Records affected: 0
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: Statement failed, SQLSTATE = 40001
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: deadlock
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR: -update conflicts with concurrent update
concurrent transaction number is
checked_mode: {checked_mode}, checked_DML = {checked_DML}, iter = 1, worker STDERR:
"""
elif checked_DML == 'del':
expected_stdout_worker = f"""
checked_mode: {checked_mode}, checked_DML = del, iter = 1, number of added rows: 11
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: Records affected: 2
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: ID
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: =======
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -13
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -12
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -11
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -10
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -9
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -8
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -7
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -6
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -5
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -4
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: -3
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: Records affected: 13
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: OLD_ID OP SNAP_NO_RANK
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: ======= ====== =====================
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 1
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 2
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 2
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 3
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 3
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 4
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 4
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 5
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 5
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 6
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 6
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 7
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 7
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 8
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 8
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 9
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 9
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 10
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 10
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 2 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: 1 DEL 11
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDLOG: Records affected: 21
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDERR: Statement failed, SQLSTATE = 40001
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDERR: deadlock
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDERR: -update conflicts with concurrent update
concurrent transaction number is
checked_mode: {checked_mode}, checked_DML = del, iter = 1, worker STDERR:
"""
act.expected_stdout = expected_stdout_worker
act.stdout = capsys.readouterr().out
> assert act.clean_stdout == act.clean_expected_stdout
E assert
E checked_mode: table, checked_DML upd, iter 0, number of added rows: 10
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: Records affected: 12
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: ID
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG:
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -1200
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -1100
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -1000
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -900
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -800
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -700
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -600
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -500
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -400
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -300
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 100
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 200
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: Records affected: 12
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: OLD_ID OP SNAP_NO_RANK
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG:
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 1
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 1
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 2
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 2
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 2
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 2
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 3
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 3
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 3
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 3
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 4
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 4
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 4
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 4
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 5
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 5
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 5
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 5
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 6
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 6
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 6
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 6
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 7
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 7
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 7
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 7
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 8
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 8
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 8
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 8
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 9
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 9
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 9
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 9
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 10
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 10
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 10
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 10
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2 UPD 11
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 2UPD 11
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1 UPD 11
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: 1UPD 11
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -3 UPD 11
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -3UPD 11
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -4 UPD 11
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -4UPD 11
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -5 UPD 11
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -5UPD 11
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -6 UPD 11
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -6UPD 11
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -7 UPD 11
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -7UPD 11
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -8 UPD 11
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -8UPD 11
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -9 UPD 11
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -9UPD 11
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -10 UPD 11
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -10UPD 11
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -11 UPD 11
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -11UPD 11
E - checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -12 UPD 11
E + checked_mode: table, checked_DML upd, iter 0, worker STDLOG: -12UPD 11
E checked_mode: table, checked_DML upd, iter 0, worker STDLOG: Records affected: 31
tests/functional/transactions/test_read_consist_sttm_restart_max_limit.py:631: AssertionError
|