Wrong rollback warnings in utPLSQL Development Environment

[PhilippSalvisberg]

Describe the bug

When I refresh my utpPLSQL development environment I get the following test result:

Warnings:
 
  1) utplsql.ut3_tester.core
      Unable to perform automatic rollback after test suite. An implicit or explicit commit/rollback occurred in procedures:
      
      Use the "--%rollback(manual)" annotation or remove commit/rollback/ddl statements that are causing the issue.
 
  2) utplsql
      Unable to perform automatic rollback after test suite. An implicit or explicit commit/rollback occurred in procedures:
      
      Use the "--%rollback(manual)" annotation or remove commit/rollback/ddl statements that are causing the issue.
 
Finished in 84.704215 seconds
888 tests, 0 failed, 0 errored, 5 disabled, 2 warning(s)

But when I rerun the tests I do not get this warnings again.

What am I doing wrong?

Provide version info

Information about utPLSQL and Database version,

19.0.0.0.0
19.0.0


PL/SQL procedure successfully completed.


UT_VERSION                                                  
------------------------------------------------------------
v3.1.8.3169-develop


BANNER                                                                           BANNER_FULL                                                                                                                                                      BANNER_LEGACY                                                                        CON_ID
-------------------------------------------------------------------------------- ---------------------------------------------------------------------------------------------------------------------------------------------------------------- -------------------------------------------------------------------------------- ----------
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production           Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production                                                                                           Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production                    0
                                                                                 Version 19.2.0.0.0                                                                                                                                                                                                                                          



PARAMETER                      VALUE                                                           
------------------------------ ----------------------------------------------------------------
NLS_LANGUAGE                   ENGLISH                                                         
NLS_TERRITORY                  SWITZERLAND                                                     
NLS_CURRENCY                   SFr.                                                            
NLS_ISO_CURRENCY               SWITZERLAND                                                     
NLS_NUMERIC_CHARACTERS         .'                                                              
NLS_CALENDAR                   GREGORIAN                                                       
NLS_DATE_FORMAT                DD.MM.YYYY HH24:MI:SS                                           
NLS_DATE_LANGUAGE              ENGLISH                                                         
NLS_SORT                       BINARY                                                          
NLS_TIME_FORMAT                HH24:MI:SSXFF                                                   
NLS_TIMESTAMP_FORMAT           DD.MM.RR HH24:MI:SSXFF                                          

PARAMETER                      VALUE                                                           
------------------------------ ----------------------------------------------------------------
NLS_TIME_TZ_FORMAT             HH24:MI:SSXFF TZR                                               
NLS_TIMESTAMP_TZ_FORMAT        DD.MM.RR HH24:MI:SSXFF TZR                                      
NLS_DUAL_CURRENCY              SF                                                              
NLS_COMP                       BINARY                                                          
NLS_LENGTH_SEMANTICS           BYTE                                                            
NLS_NCHAR_CONV_EXCP            FALSE                                                           

17 rows selected. 


PORT_STRING                                                 
------------------------------------------------------------
x86_64/Linux 2.4.xx

Information about client software

UTPLSQL_CLI_VERSION="3.1.6" (as configured in the current develop branch)

To Reproduce

1. Refresh develop branch via git
2. Run the following (excerpt of a shell script)

# local cloned utPLSQL repository, is different in your environment
cd /Users/phs/github/utPLSQL

git fetch --all
chmod +x development/*.sh
chmod +x test/*.sh
chmod +x .travis/*.sh

# configuring connection for my database for utPLSQL development
echo "export CONNECTION_STR=127.0.0.1:1521/odb.docker" >> development/env.sh

. development/env.sh
development/cleanup.sh
development/refresh_ut3.sh
development/refresh_sources.sh

# copying JARs which must not be distributed from my local SQLcl installation
cp /usr/local/bin/sqlcl/lib/ojdbc8.jar utPLSQL-cli/lib
cp /usr/local/bin/sqlcl/lib/orai*.jar utPLSQL-cli/lib

development/install.sh
test/install_and_run_tests.sh

then the results contains unexpected warnings:

Warnings:
 
  1) utplsql.ut3_tester.core
      Unable to perform automatic rollback after test suite. An implicit or explicit commit/rollback occurred in procedures:
      
      Use the "--%rollback(manual)" annotation or remove commit/rollback/ddl statements that are causing the issue.
 
  2) utplsql
      Unable to perform automatic rollback after test suite. An implicit or explicit commit/rollback occurred in procedures:
      
      Use the "--%rollback(manual)" annotation or remove commit/rollback/ddl statements that are causing the issue.
 
Finished in 84.704215 seconds
888 tests, 0 failed, 0 errored, 5 disabled, 2 warning(s)

3. Rerun the tests

cd test
time . ./${DIR}/run_tests.sh

then the result is as expected:

Finished in 62.915066 seconds
888 tests, 0 failed, 0 errored, 5 disabled, 0 warning(s)

Expected behavior

I expect the results of the subsequent runs also in the first run.

[jgebal]

This is something I've encountered several times when running self-tests with utPLSQL.
I didn't manage to get to the bottom of the problem though as it is not deterministic and only happens "sometimes".

I couldn't figure out what could be causing inconsistent transaction invalidation in the test-run.

[PhilippSalvisberg]

Just a short note, that I can reproduce this error at will.

It always happens when install utPLSQL. I've just installed the current develop branch and got the following result:

Running tests finished.
 
Warnings:
 
  1) utplsql.ut3_tester.core
      Unable to perform automatic rollback after test suite. An implicit or explicit commit/rollback occurred in procedures:
      
      Use the "--%rollback(manual)" annotation or remove commit/rollback/ddl statements that are causing the issue.
 
  2) utplsql
      Unable to perform automatic rollback after test suite. An implicit or explicit commit/rollback occurred in procedures:
      
      Use the "--%rollback(manual)" annotation or remove commit/rollback/ddl statements that are causing the issue.
 
Finished in 77.456744 seconds
903 tests, 0 failed, 0 errored, 5 disabled, 2 warning(s)

I run the following script:

START_TIME=${SECONDS}

cd /Users/phs/github/utPLSQL
git fetch --all
git pull
chmod +x development/*.sh
chmod +x test/*.sh
chmod +x .travis/*.sh
. development/env.sh
development/cleanup.sh
development/refresh_ut3.sh
development/refresh_sources.sh
development/install.sh
test/install_and_run_tests.sh

ELAPSED_TIME=$((${SECONDS}-${START_TIME}))
echo ut3 for dev installed in ${ELAPSED_TIME} seconds.

and my development/env.sh looks as follows:

#!/usr/bin/env bash

export SQLCLI=sql # For sqlcl client
export ORACLE_PWD=oracle # Adjust your local SYS password
export UTPLSQL_CLI_VERSION="3.1.8"
export SELFTESTING_BRANCH=develop

export UTPLSQL_DIR="utPLSQL_latest_release"
export UT3_OWNER=ut3
export UT3_OWNER_PASSWORD=ut3
export UT3_RELEASE_VERSION_SCHEMA=ut3_latest_release
export UT3_RELEASE_VERSION_SCHEMA_PASSWORD=ut3
export UT3_TESTER=ut3_tester
export UT3_TESTER_PASSWORD=ut3
export UT3_USER=ut3\$user#
export UT3_USER_PASSWORT=ut3
export UT3_TESTER_HELPER=ut3_tester_helper
export UT3_TESTER_HELPER_PASSWORD=ut3
export UT3_TABLESPACE=users
export UT3_USER="UT3\$USER#"
export UT3_USER_PASSWORD=ut3
export CONNECTION_STR=127.0.0.1:1521/odb.docker

[PhilippSalvisberg]

and after the failure, I can run

test/install_and_run_tests.sh

and then the result is

Running tests finished.
Finished in 66.452462 seconds
903 tests, 0 failed, 0 errored, 5 disabled, 0 warning(s)

Looks like the condition for the very first run is different and that is causing the error.

[jgebal]

I am able to reproduce it locally too.
Though in my case I didn't use your approach.
Install on clean FB caused the same issue.
When I re-install isdue no longer appears.
I will do some debugging to chase it down.

It's not critical but annnoing.

[PhilippSalvisberg]

I agree, this is low priority.

Since I updated my local installation and got this warnings again, I checked the status of this issue. And then I saw your comment about this not being "deterministic" (somehow I missed that previously). Hence, I thought it is important to point out, that it is reproducible. It has to be a bug. Either in the framework or its test suites.

[jgebal]

After some debugging I've found the problem, though it seems like Oracle issue.
We currently use a database sequence ut_savepoint_seq to get a savepoint name.
The sequence works fine and the savepoints get established at right moments.

Seems that for some reason, with a newly created sequence the savepoints get "damaged" and transaction cannot rollback.

The issue we both saw was occuring for the very first two savepoints in the run (SEQ_NO=1 and SEQNO = 1).
See attached file: test_results-problem.log

A change from sequence to a timestamp made it go away and I can no longer reproduce the issue

I'm not sure if there is an Oracle bug for it.
If you want @PhilippSalvisberg you can dig a bit deeper to see if it can be distilled into reproducible test-case for Oracle to investigate.

For now I'll change from sequence to timestamp by replacing line
from:
return 's'||trim(to_char(ut_savepoint_seq.nextval,'0000000000000000000000000000'));
to:
return 's'||to_char(systimestamp,'yyyymmddhh24missff9');

[PhilippSalvisberg]

I had a deeper look while reviewing #1027 .

It is not an Oracle bug. It's a bug of the utPLSQL test setup. It's a namespace clash between the ut3 and the ut3_latest_release schema. Both schemas own a sequence named ut_savepoint_seq. During test execution both sequences are used to generate savepoint names within the very same Oracle session. This leads to these warnings... after the initial run difference in the sequence numbers is large enough to not cause this warnings on subsequent runs.

I can reproduce it by running this with this script:

connect ut3_latest_release/XNtxj8eEgA6X6b6f@odb190
alter sequence ut_savepoint_seq restart;
connect ut3/ut3@odb190
alter sequence ut_savepoint_seq restart;
connect ut3_tester_helper/ut3@odb190
set serveroutput on size unlimited
begin
   ut.run('ut3_tester');
end;
/

A simple fix is to use the owner of the PL/SQL package in the name of the savepoint. Changing the package function ut_utils.gen_savepoint_name to something like this:

  function gen_savepoint_name return varchar2 is
  begin
    return 's' ||  $$plsql_unit_owner || trim(to_char(ut_savepoint_seq.nextval));
  end;

After that change I do not get these warnings anymore.

[jgebal]

Thanks for digging @PhilippSalvisberg
It never occured to me that this could be causing the issue.
I agree that making sure savepoint-name is unique within session is important.

To your point on not using timestamp...
Is it really possible to have 2 savepoints created within single session (thread) in interval < 1microsecond?
Not sure if any OS gives miliseconds only.

The challenge with appending username is the lenght limit on savepoint name.

Even UUID is too long ..

[PhilippSalvisberg]

Actually my OS delivers only microseconds:

SQL> select to_char(systimestamp,'DD.MM.YYYY HH24:MI:SS.FF9') from dual;
TO_CHAR(SYSTIMESTAMP,'DD.MM.Y
-----------------------------
30.11.2019 16:09:10.876105000

The last 3 digits are always zero.

I do not think it is a real problem using a timestamp. I just stated that I do not like to rely on slow processing.

Regarding the naming restriction. 30 bytes is valid for 11.2 and 12.1. Both versions are end of live. We can write the code in a way to use the 128 bytes. We can even define the sequence using the CYCLE clause. In fact, we do not need a large range. The range must just be large enough to cover a single Oracle session. Typically one test run. So 9-12 digits should be really enough. The rest can be the user name limited to 15-18 chars (in Oracle Database versions < 12.2).