Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Attempt to drop existing user randomly fails with "336723990 : record not found for user" [CORE6080] #6330

Closed
firebird-automations opened this issue Jun 10, 2019 · 13 comments

Comments

@firebird-automations
Copy link
Collaborator

Submitted by: @pavel-zotov

This ticket was created by Vlad request after discuss failures in test for CORE6038 when it is launched
Consider following batch:

@echo off
setlocal enabledelayedexpansion enableextensions
for /f "delims=." %%a in ('wmic os get localdatetime ^| findstr /i /r /b /c:"[0-9]"') do (
set dts=%%a
set ymd=!dts:~2,6!
set hms=!dts:~8,6!
)

set fbc=C:\FB\40CS
set dbpath=c:\temp
set authplg=Srp
@Rem set authplg=Legacy_UserManager

set dbnm=!dbpath!\c6038.fdb.tmp
set sql=!dbpath!\%~n0.sql.tmp
set tmp=!dbpath!\%~n0.tmp.tmp
set err=!dbpath!\%~n0.err.tmp

set log=%~dpn0.!ymd!_!hms!.log

if exist !dbnm! del !dbnm!
(
echo set bail on;
echo create database 'localhost:!dbnm!' user sysdba password 'masterkey';
echo commit;
echo alter database set linger to 30;
echo commit;
echo show database;
) >!tmp!
!fbc!\isql.exe -z -q -i !tmp!

!fbc!\gfix.exe -w async localhost:!dbnm! -user sysdba -password masterkey

(
echo connect 'localhost:!dbnm!' user sysdba password 'masterkey';
echo create or alter user c6038_srp password 'c6038_srp' using plugin !authplg!;
echo commit;
echo connect 'localhost:!dbnm!' user c6038_srp password 'c6038_srp';
echo commit;
echo connect 'localhost:!dbnm!' user sysdba password 'masterkey';
echo drop user c6038_srp using plugin !authplg!;
) > !sql!

!fbc!\fbsvcmgr.exe localhost:service_mgr user sysdba password masterkey info_server_version >!tmp!
type !tmp!
type !tmp! >>!log!
echo !date! !time! Started.

if exist !err! del !err!
set verb=1
set /a n=300
set /a i=0
:m1
set /a i=!i!+1
if !verb! EQU 1 (
echo !date! !time!, attempt !i! >!tmp!
type !tmp!
type !tmp! >>!log!
del !tmp!
for /f "usebackq tokens=*" %%a in ('!err!') do set size=%%~za
if !size! gtr 0 (
echo CONNECTION FAILED IN ITERATION #⁠ !i!. CHECK ERROR LOG:
type !err!
type !err! >>!log!
exit
)
)
!fbc!\isql.exe -q -i !sql! 1>>!err! 2>&1
if !i! GEQ !n! (
echo !date! !time! Completed.
for /f "usebackq tokens=*" %%a in ('!err!') do set size=%%~za
if !size! gtr 0 (
echo CHECK ERROR LOG AFTER ALL ITERATIONS:
type !err!
type !err! >>!log!
)
exit
)
goto m1

Change in it only these three settings: fbc, dbpath and authplg.
Prepare FB to work as Classic and run this batch.

On WI-T4.0.0.1524 you will soon encounter with:

10.06.2019 18:13:19.67, attempt 1
10.06.2019 18:13:20.72, attempt 2
. . .
10.06.2019 18:13:49.75, attempt 27
10.06.2019 18:13:50.79, attempt 28
Statement failed, SQLSTATE = HY000
modify record error
After line 1 in file c:\temp\c6038.leg.sql.tmp
Statement failed, SQLSTATE = 28000
Your user name and password are not defined. Ask your database administrator to set up a Firebird login.
After line 3 in file c:\temp\c6038.leg.sql.tmp
Statement failed, SQLSTATE = HY000
record not found for user: C6038_SRP

Trace with 'log_prepare_statements = true' will show:

1) TWO prepare_statement events before point when error raises:

PREPARE_STATEMENT
drop user c6038_srp using plugin Srp
....
PREPARE_STATEMENT
drop user c6038_srp using plugin Srp

2) SUCCESSFUL finish of executed statement:

EXECUTE_STATEMENT_FINISH
drop user c6038_srp using plugin Srp
0 records fetched
0 ms

and immediately after this - error:

3) ERROR AT JTransaction::commit
C:\TEMP\C6038.FDB.TMP (ATT_55, SYSDBA:NONE, NONE, TCPv6:::1/63982)
C:\FB\40SS\isql.exe:5124
336723990 : record not found for user: C6038_SRP

Commits: d368300 3bfa5fa

====== Test Details ======

Test not needed - see CORE6038 (current ticket was created after fails of core_6038.fbt for 4.0 Cs).
Checked on 4.0.0.1530 Classic mode, ran 262 iterations -- all fine (previous builds failed at ~20...30 th iter.)

@firebird-automations
Copy link
Collaborator Author

Modified by: @hvlad

assignee: Vlad Khorsun [ hvlad ]

@firebird-automations
Copy link
Collaborator Author

Commented by: @hvlad

The issue is introduced in fb4 with a new implementation od TIP cache and related with initialization of few shared memory blocks as single atomic operation

@firebird-automations
Copy link
Collaborator Author

Modified by: @hvlad

status: Open [ 1 ] => Resolved [ 5 ]

resolution: Fixed [ 1 ]

Fix Version: 4.0 Beta 2 [ 10888 ]

@firebird-automations
Copy link
Collaborator Author

Modified by: Sean Leyne (seanleyne)

Component: Engine [ 10000 ]

description: This ticket was created by Vlad request after discuss failures in test for CORE6038 when it is launched. It seems that only 4.0 Classic is affected.
Consider following batch:

@echo off
setlocal enabledelayedexpansion enableextensions
for /f "delims=." %%a in ('wmic os get localdatetime ^| findstr /i /r /b /c:"[0-9]"') do (
set dts=%%a
set ymd=!dts:~2,6!
set hms=!dts:~8,6!
)

set fbc=C:\FB\40CS
set dbpath=c:\temp
set authplg=Srp
@Rem set authplg=Legacy_UserManager

set dbnm=!dbpath!\c6038.fdb.tmp
set sql=!dbpath!\%~n0.sql.tmp
set tmp=!dbpath!\%~n0.tmp.tmp
set err=!dbpath!\%~n0.err.tmp

set log=%~dpn0.!ymd!_!hms!.log

if exist !dbnm! del !dbnm!
(
echo set bail on;
echo create database 'localhost:!dbnm!' user sysdba password 'masterkey';
echo commit;
echo alter database set linger to 30;
echo commit;
echo show database;
) >!tmp!
!fbc!\isql.exe -z -q -i !tmp!

!fbc!\gfix.exe -w async localhost:!dbnm! -user sysdba -password masterkey

(
echo connect 'localhost:!dbnm!' user sysdba password 'masterkey';
echo create or alter user c6038_srp password 'c6038_srp' using plugin !authplg!;
echo commit;
echo connect 'localhost:!dbnm!' user c6038_srp password 'c6038_srp';
echo commit;
echo connect 'localhost:!dbnm!' user sysdba password 'masterkey';
echo drop user c6038_srp using plugin !authplg!;
) > !sql!

!fbc!\fbsvcmgr.exe localhost:service_mgr user sysdba password masterkey info_server_version >!tmp!
type !tmp!
type !tmp! >>!log!
echo !date! !time! Started.

if exist !err! del !err!
set verb=1
set /a n=300
set /a i=0
:m1
set /a i=!i!+1
if !verb! EQU 1 (
echo !date! !time!, attempt !i! >!tmp!
type !tmp!
type !tmp! >>!log!
del !tmp!
for /f "usebackq tokens=*" %%a in ('!err!') do set size=%%~za
if !size! gtr 0 (
echo CONNECTION FAILED IN ITERATION #⁠ !i!. CHECK ERROR LOG:
type !err!
type !err! >>!log!
exit
)
)
!fbc!\isql.exe -q -i !sql! 1>>!err! 2>&1
if !i! GEQ !n! (
echo !date! !time! Completed.
for /f "usebackq tokens=*" %%a in ('!err!') do set size=%%~za
if !size! gtr 0 (
echo CHECK ERROR LOG AFTER ALL ITERATIONS:
type !err!
type !err! >>!log!
)
exit
)
goto m1

Change in it only these three settings: fbc, dbpath and authplg.
Prepare FB to work as Classic and run this batch.

On WI-T4.0.0.1524 you will soon encounter with:

10.06.2019 18:13:19.67, attempt 1
10.06.2019 18:13:20.72, attempt 2
. . .
10.06.2019 18:13:49.75, attempt 27
10.06.2019 18:13:50.79, attempt 28
Statement failed, SQLSTATE = HY000
modify record error
After line 1 in file c:\temp\c6038.leg.sql.tmp
Statement failed, SQLSTATE = 28000
Your user name and password are not defined. Ask your database administrator to set up a Firebird login.
After line 3 in file c:\temp\c6038.leg.sql.tmp
Statement failed, SQLSTATE = HY000
record not found for user: C6038_SRP

Trace with 'log_prepare_statements = true' will show:

1) TWO prepare_statement events before point when error raises:

PREPARE_STATEMENT
drop user c6038_srp using plugin Srp
....
PREPARE_STATEMENT
drop user c6038_srp using plugin Srp

2) SUCCESSFUL finish of executed statement:

EXECUTE_STATEMENT_FINISH
drop user c6038_srp using plugin Srp
0 records fetched
0 ms

and immediately after this - error:

3) ERROR AT JTransaction::commit
C:\TEMP\C6038.FDB.TMP (ATT_55, SYSDBA:NONE, NONE, TCPv6:::1/63982)
C:\FB\40SS\isql.exe:5124
336723990 : record not found for user: C6038_SRP

=>

This ticket was created by Vlad request after discuss failures in test for CORE6038 when it is launched
Consider following batch:

@echo off
setlocal enabledelayedexpansion enableextensions
for /f "delims=." %%a in ('wmic os get localdatetime ^| findstr /i /r /b /c:"[0-9]"') do (
set dts=%%a
set ymd=!dts:~2,6!
set hms=!dts:~8,6!
)

set fbc=C:\FB\40CS
set dbpath=c:\temp
set authplg=Srp
@Rem set authplg=Legacy_UserManager

set dbnm=!dbpath!\c6038.fdb.tmp
set sql=!dbpath!\%~n0.sql.tmp
set tmp=!dbpath!\%~n0.tmp.tmp
set err=!dbpath!\%~n0.err.tmp

set log=%~dpn0.!ymd!_!hms!.log

if exist !dbnm! del !dbnm!
(
echo set bail on;
echo create database 'localhost:!dbnm!' user sysdba password 'masterkey';
echo commit;
echo alter database set linger to 30;
echo commit;
echo show database;
) >!tmp!
!fbc!\isql.exe -z -q -i !tmp!

!fbc!\gfix.exe -w async localhost:!dbnm! -user sysdba -password masterkey

(
echo connect 'localhost:!dbnm!' user sysdba password 'masterkey';
echo create or alter user c6038_srp password 'c6038_srp' using plugin !authplg!;
echo commit;
echo connect 'localhost:!dbnm!' user c6038_srp password 'c6038_srp';
echo commit;
echo connect 'localhost:!dbnm!' user sysdba password 'masterkey';
echo drop user c6038_srp using plugin !authplg!;
) > !sql!

!fbc!\fbsvcmgr.exe localhost:service_mgr user sysdba password masterkey info_server_version >!tmp!
type !tmp!
type !tmp! >>!log!
echo !date! !time! Started.

if exist !err! del !err!
set verb=1
set /a n=300
set /a i=0
:m1
set /a i=!i!+1
if !verb! EQU 1 (
echo !date! !time!, attempt !i! >!tmp!
type !tmp!
type !tmp! >>!log!
del !tmp!
for /f "usebackq tokens=*" %%a in ('!err!') do set size=%%~za
if !size! gtr 0 (
echo CONNECTION FAILED IN ITERATION #⁠ !i!. CHECK ERROR LOG:
type !err!
type !err! >>!log!
exit
)
)
!fbc!\isql.exe -q -i !sql! 1>>!err! 2>&1
if !i! GEQ !n! (
echo !date! !time! Completed.
for /f "usebackq tokens=*" %%a in ('!err!') do set size=%%~za
if !size! gtr 0 (
echo CHECK ERROR LOG AFTER ALL ITERATIONS:
type !err!
type !err! >>!log!
)
exit
)
goto m1

Change in it only these three settings: fbc, dbpath and authplg.
Prepare FB to work as Classic and run this batch.

On WI-T4.0.0.1524 you will soon encounter with:

10.06.2019 18:13:19.67, attempt 1
10.06.2019 18:13:20.72, attempt 2
. . .
10.06.2019 18:13:49.75, attempt 27
10.06.2019 18:13:50.79, attempt 28
Statement failed, SQLSTATE = HY000
modify record error
After line 1 in file c:\temp\c6038.leg.sql.tmp
Statement failed, SQLSTATE = 28000
Your user name and password are not defined. Ask your database administrator to set up a Firebird login.
After line 3 in file c:\temp\c6038.leg.sql.tmp
Statement failed, SQLSTATE = HY000
record not found for user: C6038_SRP

Trace with 'log_prepare_statements = true' will show:

1) TWO prepare_statement events before point when error raises:

PREPARE_STATEMENT
drop user c6038_srp using plugin Srp
....
PREPARE_STATEMENT
drop user c6038_srp using plugin Srp

2) SUCCESSFUL finish of executed statement:

EXECUTE_STATEMENT_FINISH
drop user c6038_srp using plugin Srp
0 records fetched
0 ms

and immediately after this - error:

3) ERROR AT JTransaction::commit
C:\TEMP\C6038.FDB.TMP (ATT_55, SYSDBA:NONE, NONE, TCPv6:::1/63982)
C:\FB\40SS\isql.exe:5124
336723990 : record not found for user: C6038_SRP

summary: Attempt to drop existing user randomly fails with "336723990 : record not found for user" on Classic (4.0 only is affected) => Attempt to drop existing user randomly fails with "336723990 : record not found for user"

environment: v4 Classic Server only

@firebird-automations
Copy link
Collaborator Author

Modified by: @pavel-zotov

status: Resolved [ 5 ] => Resolved [ 5 ]

QA Status: No test => Covered by another test(s)

Test Details: Test not needed - see CORE6038 (current ticket was created after fails of core_6038.fbt for 4.0 Cs).
Checked on 4.0.0.1530 Classic mode, ran 262 iterations -- all fine (previous builds failed at ~20...30 th iter.)

@firebird-automations
Copy link
Collaborator Author

Modified by: @pavel-zotov

status: Resolved [ 5 ] => Closed [ 6 ]

@firebird-automations
Copy link
Collaborator Author

Commented by: @artyom-smirnov

Looks like fix for this issue caused some regressions. Test bugs.core_2018 hanging server on Classic (all OK on Super) after commit 3bfa5fa.

Two hanged server processes backtraces:

https://gist.github.com/artyom-smirnov/1954fa1cd58f6886784a5dca9f7152cb

https://gist.github.com/artyom-smirnov/30cd05ab7b28326bf8195e3746985b10

Isql backtrace:

https://gist.github.com/artyom-smirnov/cf3c452a13f4ea206cea980fe6a5f3bd

@firebird-automations
Copy link
Collaborator Author

Commented by: @hvlad

Re-opened to fix a bug, introduced by initial attempt

@firebird-automations
Copy link
Collaborator Author

Modified by: @hvlad

status: Closed [ 6 ] => Reopened [ 4 ]

resolution: Fixed [ 1 ] =>

@firebird-automations
Copy link
Collaborator Author

Commented by: @hvlad

Should be fixed now.

@firebird-automations
Copy link
Collaborator Author

Commented by: @hvlad

Artyom, Pavel : could you verify last fix and let me close the ticket, please ?

@firebird-automations
Copy link
Collaborator Author

Commented by: @pavel-zotov

I confirm that there are no problems in Classic with test for core-2018 when it is launched on following builds:
1) 4.0.0.1556: OK, 2.929s.
2) 3.0.5.33152: OK, 2.157s.

@firebird-automations
Copy link
Collaborator Author

Modified by: @hvlad

status: Reopened [ 4 ] => Resolved [ 5 ]

resolution: Fixed [ 1 ]

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants