Issue Details (XML | Word | Printable)

Key: CORE-4239
Type: Bug Bug
Status: Resolved Resolved
Resolution: Fixed
Priority: Major Major
Assignee: Unassigned
Reporter: Kovalenko Dmitry
Votes: 0
Watchers: 4
Operations

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

AV. Problem in MET_procedure

Created: 27/Sep/13 08:08 AM   Updated: 23/Jul/19 02:38 PM
Component/s: Engine
Affects Version/s: 2.5.3
Fix Version/s: 3.0.0, 4.0 Alpha 1

Environment:
Vista x64. Q6600, 8GB. IBProvider Test System.


 Description  « Hide
I executed my old tests (in four threads) and get the (think, reproducible) AV in Firebird's engine:

Необработанное исключение в "0x0000000140256da2" в "fb_inet_server.exe": 0xC0000005: Нарушение прав доступа при записи "0x0000000000000000".

----------
[27.09.2013 08:54:24] [ExecuteTests] CommandLine:

target\ibp_oledb_test_vc10_x64_Release.exe /thread_count 4 /log_dir ..\_log /log_file_prefix w64_local_d3 /cn_str "provider=LCPI.IBProvider.3;location=d:\database\ibp_test_fb25_d3.gdb;user id=gamer;password=vermut;ctype=win1251;icu_library=icuuc30.dll" /test schema*

[27.09.2013 08:54:24] [ExecuteTests] Test Mask : [schema*]

[27.09.2013 08:54:24] [info] Provider DLL :_IBProvider_v3_vc10_w64_i.dll
[27.09.2013 08:54:24] [info] Provider Version:3.16.4.15390
[27.09.2013 08:54:24] [info] Server Name :Firebird x64 [SuperClassic]. Release build [VS2010]
[27.09.2013 08:54:24] [info] Server Version :2.5.3.26640
[27.09.2013 08:54:24] [info] Client Name :Firebird SQL Server
[27.09.2013 08:54:24] [info] Client Version :2.5.3.26640
[27.09.2013 08:54:24] [info] Database ODS :11.2
[27.09.2013 08:54:24] [info] Database Dialect:3

---------------- [problem FB-thread stack]

[SRC]
Parameter* parameter = *ptr;
// check for parameter to be null, this can only happen if the
// parameter numbers get out of sync. This was added to fix bug
// 10534. -Shaunak Mistry 12-May-99
if (parameter)
{
*desc = parameter->prm_desc; //<---------------- HERE
length = MET_align(dbb, &(*desc), length);
desc->dsc_address = (UCHAR *) (IPTR) length;
length += desc->dsc_length;
}

[ASM]
if (parameter)
0000000140256D99 test rcx,rcx
0000000140256D9C je 0000000140256DF1
{
*desc = parameter->prm_desc;
0000000140256D9E mov rax,qword ptr [rcx+8]
0000000140256DA2 mov qword ptr [r8],rax //<------------ HERE

[STACK]
> fb_inet_server.exe!MET_procedure(Jrd::thread_db * tdbb=0x305f504d545f5053, int id=67718520, bool noscan=true, unsigned short flags=61472) Строка 5067 + 0x4 байт C++
  fb_inet_server.exe!MET_lookup_procedure(Jrd::thread_db * tdbb=0x00000000053af020, const Firebird::MetaName & name={...}, bool noscan=false) Строка 3979 + 0x14 байт C++
  fb_inet_server.exe!create_procedure(Jrd::thread_db * tdbb=0x000000000c99b608, short phase=-27224, Jrd::DeferredWork * work=0x000000000f2f3368, Jrd::jrd_tra * transaction=0x0000000000000001) Строка 3468 C++
  fb_inet_server.exe!DFW_perform_work(Jrd::thread_db * tdbb=0x000000000c99b608, Jrd::jrd_tra * transaction=0x0000000000000000) Строка 1174 + 0x11 байт C++
  fb_inet_server.exe!TRA_commit(Jrd::thread_db * tdbb=0x000000000f2f3368, Jrd::jrd_tra * transaction=0x0000000000000000, const bool retaining_flag=true) Строка 444 C++
  fb_inet_server.exe!commit(Jrd::thread_db * tdbb=0x00000000053af270, Jrd::jrd_tra * transaction=0x00000000053af9b0, const bool retaining_flag=true) Строка 4539 + 0xf байт C++
  fb_inet_server.exe!jrd8_commit_transaction(__int64 * user_status=0x000000000eed4720, Jrd::jrd_tra * * tra_handle=0x000000000efc0198) Строка 1744 + 0x13 байт C++
  fb_inet_server.exe!isc_commit_transaction(__int64 * user_status=0x000000000eed4720, unsigned int * tra_handle=0x0000000007178910) Строка 1749 + 0x34 байт C++
  fb_inet_server.exe!rem_port::end_transaction(P_OP operation=118982928, p_rlse * release=0x0000000007178910, packet * sendL=0x0000000007178910) Строка 2086 C++
  fb_inet_server.exe!process_packet(rem_port * port=0x0000000000db0020, packet * sendL=0x0000000007178910, packet * receive=0x0000000000dba7a8, rem_port * * result=0x0000000000000038) Строка 3419 C++
  fb_inet_server.exe!SRVR_main(rem_port * main_port=0x00000000043a6f00, unsigned short flags=0) Строка 402 + 0x1a байт C++
  fb_inet_server.exe!process_connection_thread(void * arg=0x00000000043a6f10) Строка 348 + 0x14 байт C++
  fb_inet_server.exe!`anonymous namespace'::threadStart(void * arg=0x0000000000000000) Строка 139 + 0x5 байт C++

---------------- [problem FB-thread local vars]
+ tdbb 0x305f504d545f5053 {tdbb_default=??? database=??? attachment=??? ...} Jrd::thread_db *
id 67718520 int
noscan true bool
flags 61472 unsigned short
+ jrd_160 {jrd_161=0x00000000053aeb20 "IN4 " jrd_162=0x00000000053aeb40 "SP_TMP_007_32096 " } MET_procedure::__l2::<unnamed-type-jrd_160>
+ jrd_151 {jrd_152=0 } MET_procedure::__l2::<unnamed-type-jrd_151>
+ procedure 0x0000000004022060 {prc_id=677 prc_flags=8 prc_inputs=4 ...} Jrd::jrd_prc *
+ jrd_190 {jrd_191={...} jrd_192=0x00000000053aea08 "SQL$32855 " jrd_193=0x00000000053aea28 "SP_TMP_007_32096 " ...} MET_procedure::__l2::<unnamed-type-jrd_190>
+ jrd_170 {jrd_171=0x00000000053aeb00 "SP_TMP_007_32096 " } MET_procedure::__l2::<unnamed-type-jrd_170>
+ dbb 0x0000000002c2de10 {dbb_sync={...} dbb_lock_mgr=0x0000000000dbeb58 dbb_event_mgr=0x0000000000000000 ...} Jrd::Database *
+ jrd_153 {jrd_154={...} jrd_155=27680 jrd_156=1486 ...} MET_procedure::__l2::<unnamed-type-jrd_153>
+ jrd_188 {jrd_189=677 } MET_procedure::__l2::<unnamed-type-jrd_188>
+ jrd_172 {jrd_173={...} jrd_174=0x00000000053aea88 "RDB$126807 " jrd_175=0x00000000053aeaa8 "IN4 " ...} MET_procedure::__l2::<unnamed-type-jrd_172>
+ jrd_163 {jrd_164={...} jrd_165=0 jrd_166=-1 ...} MET_procedure::__l2::<unnamed-type-jrd_163>
+ guard {mutex={...} } Jrd::Database::CheckoutLockGuard
+ csb_pool 0x0000000004094d78 {parent_redirect=true freeBlocks={...} extents_os=0x0000000000001770 ...} Firebird::MemoryPool *
+ pa_default_value {bid_internal={...} bid_quad={...} } Jrd::bid
+ pool 0x0000000004095928 {parent_redirect=true freeBlocks={...} extents_os=0x0000000004095fe0 ...} Firebird::MemoryPool *
+ context {savedThreadData=0x0000000000000000 savedPool=0x000000000c99b608 } Firebird::SubsystemContextPoolHolder<Jrd::thread_db,Firebird::MemoryPool>
+ csb {ptr=0x0000000004094d78 } Firebird::AutoPtr<Jrd::CompilerScratch,Firebird::SimpleDelete<Jrd::CompilerScratch> >
+ context {savedThreadData=0x00000000053af020 savedPool=0x0000000000000000 } Firebird::SubsystemContextPoolHolder<Jrd::thread_db,Firebird::MemoryPool>
+ csb {ptr=0x0000000004095928 } Firebird::AutoPtr<Jrd::CompilerScratch,Firebird::SimpleDelete<Jrd::CompilerScratch> >

Unfortunately, because I used "release" Firebird's binaries, I have the problem with the exact information about all local variables.

------------ [IBProvider test thread]
[THR:006088] [27.09.2013 11:05:19] [test] Prepare Command:

"CREATE PROCEDURE SP_TMP_007_32096
(IN1 VARCHAR(31) CHARACTER SET UNICODE_FSS,
IN2 BLOB SUB_TYPE 1 SEGMENT SIZE 256,
IN3 SMALLINT,
IN4 BLOB SUB_TYPE 0 SEGMENT SIZE 256)
AS
 DECLARE VARIABLE X INTEGER;
BEGIN
 X=0;
END"

[THR:006088] [27.09.2013 11:05:19] [test] EXECUTE COMMAND (or=true,rpi=true) [NO PARAMS] ...
[THR:006088] [27.09.2013 11:05:19] [test] COMMIT TRANSACTION [RETAINING=false]...
<AV in FB engine>


 All   Comments   Change History   Subversion Commits      Sort Order: Ascending order - Click to sort in descending order
Adriano dos Santos Fernandes added a comment - 27/Sep/13 02:50 PM
Is multiple threads required to crash?

Does the crash happens in every run?

Kovalenko Dmitry added a comment - 27/Sep/13 04:15 PM - edited
>Is multiple threads required to crash?

I think, yes.

Rules:
- Only one DDL statement execute in each time (isc_dsql_execute for DDL). It not lock the other operations (start_tr, commit_tr, prepare_stmt, execute_stmt for DML ...)
- Other operations (start_tr, commit_tr, prepare_stmt ...) can be performed in parallel

Each thread uses own connection (local protocol).

>Does the crash happens in every run?

I ran this set of tests twice. And twice got the AV (within 2 hours after start) in more or less equal situations. I have the logs in both cases.

[------------------ TEST_THREAD1]

This thread reads the system tables. No any DDL.

[THR:003668] [27.09.2013 09:04:52] [read_schema] Fetch schema data [Test Restrictions]
<resume execution of FB>
[THR:003668] [27.09.2013 14:50:52] ERROR: [read_schema] Schema DBSCHEMA_COLUMN_PRIVILEGES [{C8B52221-5CF3-11CE-ADE5-00AA0044773D}]
Open schema {C8B52221-5CF3-11CE-ADE5-00AA0044773D}
1. [LCPI.IBProvider.3]: Cursor fetch row failed.

Error reading data from the connection.

[------------------ TEST_THREAD2]
[THR:006088] [27.09.2013 11:05:19] [test] Prepare Command:

"CREATE PROCEDURE SP_TMP_007_32096
(IN1 VARCHAR(31) CHARACTER SET UNICODE_FSS,
IN2 BLOB SUB_TYPE 1 SEGMENT SIZE 256,
IN3 SMALLINT,
IN4 BLOB SUB_TYPE 0 SEGMENT SIZE 256)
AS
 DECLARE VARIABLE X INTEGER;
BEGIN
 X=0;
END"

[THR:006088] [27.09.2013 11:05:19] [test] EXECUTE COMMAND (or=true,rpi=true) [NO PARAMS] ...
[THR:006088] [27.09.2013 11:05:19] [test] COMMIT TRANSACTION [RETAINING=false]... <----------- STOP FB IN DEBUGER
<resume execution of FB>
[THR:006088] [27.09.2013 14:50:52] ERROR: [schema|schema.007.sp_text.03.IN_4.sp_3711] Commit transaction
1. [LCPI.IBProvider.3]: Transaction commit failed. Transaction will be aborted.

connection lost to database

[------------------ TEST_THREAD3]
[THR:005932] [27.09.2013 11:05:19] [test] START TRANSACTION ...
<resume execution of FB>
[THR:005932] [27.09.2013 14:50:52] [test] GENERATE ID [GEN_ID_DDL]. Count:1...
[THR:005932] [27.09.2013 14:50:52] ERROR: [schema|schema.007.sp_text.03.IN_4.sp_3712] Fetching of rows
1. [LCPI.IBProvider.3]: Cursor fetch row failed.

Error reading data from the connection.

[------------------ TEST_THREAD4]
[THR:005864] [27.09.2013 11:05:19] [test] Create command ...
[THR:005864] [27.09.2013 11:05:19] [test] START TRANSACTION ...
<resume execution of FB>
[THR:005864] [27.09.2013 14:50:52] [test] GENERATE ID [GEN_ID_DDL]. Count:1...
[THR:005864] [27.09.2013 14:50:52] ERROR: [schema|schema.007.sp_text.03.IN_4.sp_3713] Fetching of rows
1. [LCPI.IBProvider.3]: Cursor fetch row failed.

Error reading data from the connection.

------------------
At current time, I try to reproduce this problem with debug build of FB.

Kovalenko Dmitry added a comment - 28/Sep/13 05:34 AM
With debug build I cannot reproduce this problem :(

But with release build (include build from latest source of FB) - no problem.

http://www.ibprovider.com/download/fb/2013_09_28__fb_crash__001.7z [30MB]

Vlad Khorsun added a comment - 08/Dec/13 10:26 AM
The issue is related to procedure SP_TMP_007_8.
Could you tell us if this procedure created once or it was recreated or altered ?
Could you show us all DDL statements with this procedure ?

Kovalenko Dmitry added a comment - 08/Dec/13 10:53 AM
>Could you tell us if this procedure created once or it was recreated or altered ?

All procedures were created and deleted at test time.

No "recreate" or "alter" operations.

Only "create" and "drop" operations.

Each test:
0. Create connection
1. Start Transaction1. Creates Test Stored Procedure. Commit.
2. Start Transaction2. Reads information from RDB$PROCEDURES, RDB$PROCEDURE_PARAMETERS for this Test Stored Procedure. Commit.
3. Start Transaction3. Deletes this Test Stored Procedure. Commit.

At each time works 8 test threads.

>Could you show us all DDL statements with this procedure ?

1. CREATE PROCEDURE ...;
2. DROP PROCEDURE ...;

Alexander Peshkov added a comment - 23/Jul/19 01:58 PM
The bug was finally reproduced by IbPhoenix & GLDS. The reason was very bad code working with vectors of procedure parameters. That was fixed be Adriano in FB3 initial but was not backprted to 2.5. Due to finished lifecycle of 2.5 and missing of complete fix in 2.5.9 I mark bug as fixed only in FB 3 & 4.

Alexander Peshkov made changes - 23/Jul/19 01:58 PM
Field Original Value New Value
Status Open [ 1 ] Resolved [ 5 ]
Fix Version/s 4.0 Alpha 1 [ 10731 ]
Fix Version/s 3.0.0 [ 10740 ]
Resolution Fixed [ 1 ]
Kovalenko Dmitry added a comment - 23/Jul/19 02:38 PM
Wow, thanks :)