ORA-03124 Two-task internal error running Django migrations

[danizen]

1. What is your version of Python? Is it 32-bit or 64-bit?

Python 3.6.3 (64-bit) on CentOS 6.10. This is from CentOS SCL repository:

$ rpm -q rh-python36-python 
rh-python36-python-3.6.3-3.el6.x86_64

2. What is your cx_Oracle version?

cx-Oracle 6.4.1 - we have reproduced with both the manylinux1 build and a build created as follows:

pip uninstall -y cx-Oracle
pip install --no-cache --index https://pypi.org/simple --no-binary cx-Oracle cx-Oracle==6.4.1

We found that this no longer occurs with home-built versions of cx-Oracle 5.2.1 and cx-Oracle 5.3.

3. What exact command caused the problem (e.g. what command did you try to install with)?

./manage.py migrate

Who were you logged in as?

davisda4, but this is also occurring in our CI/CD environment.

4. What error(s) you are seeing?

During Django migrations, we see a traceback from
django.db.utils.DatabaseError: ORA-03124: two-task internal error. This Django exception class is a wrapper for multiple database vendor specific errors. We are assuming the Oracle error number is of sufficient detail. See the attached file for full log information:

fulldebug.log

The pid/tid come from %(process)d and %(thread)d in the python logging formatter. Analyzing django/db/backends/utils.py confirms that the last SQL statement in this full log was the one on which the problem occurred. Note that there are no migrations, and so this is stock Django 1.11.20.

5. What OS (and version) is Python executing on?

CentOS 6.10

6. What is your version of the Oracle client (e.g. Instant Client)? How was it installed? Where is it installed?

12.1.0.1

Note that Django 1.11.20 was used. I cannot easily update to cx_Oracle 7+ without also updating to Django 2.2, which my organization is not yet ready to do.

I am not sure how it was installed, but the instantclient rpms are not installed
/usr/nlm/share/oracle/12.1.0.1 - this is a read-only NFS mount

7. What is your Oracle Database version?

Oracle 18c

8. What is the PATH environment variable (on Windows) or LD_LIBRARY_PATH (on Linux) set to? On macOS, what is in ~/lib?

$ echo $LD_LIBRARY_PATH
/opt/rh/rh-python36/root/usr/lib64:/usr/nlm/share/oracle/12.1.0.1/lib

9. What Oracle environment variables did you set? How exactly did you set them?

This is an expert from my .bashrc:

ORACLE_HOME=/usr/nlm/share/oracle/12.1.0.1
TNS_ADMIN=/usr/nlm/share/etc/tns_admin
NLS_LANG="AMERICAN_AMERICA.UTF8"

# Put oracle's pelr libraires into PERL5LIB
if [ -z "$ORAPERL" ]; then
    ORAPERL=/usr/nlm/share/oracle/12.1.0.1/perl
    PERL5LIB="$ORAPERL/lib/5.14.1:$ORAPERL/lib/site_perl/5.14.1";
    export PERL5LIB
fi
export ORACLE_SID
export ORACLE_HOME
export ORACLE_PERL
export PERL5LIB
export TNS_ADMIN
export NLS_LANG

if [[ -z "$LD_LIBRARY_PATH" ]]; then
    LD_LIBRARY_PATH=$ORACLE_HOME/lib
else
    [[ $LD_LIBRARY_PATH =~ $ORACLE_HOME ]] || LD_LIBRARY_PATH="$ORACLE_HOME/lib:$LD_LIBRARY_PATH"
fi
export LD_LIBRARY_PATH

10. Do you have a small, single Python script that immediately runs to show us the problem?

Not as yet.

11. Additional Notes

We also submitted through our vendor support channel as SR 3-20049808601, with title "Client connection failing on with ORA-03124 Two-task internal error".

[cjbj]

@danizen this will require a parallel approach to solve since you are working with multiple open source projects.

The ORA error number necessarily is too broad to identity a specific cause. The trace file is for Django, and doesn't mean a lot to us. In particular it's not clear to me whether those SQL statements are executed when they are printed, and what the column and bind types are.

Even if Oracle Support won't handle (the open source) cx_Oracle, and certainly don't look after the 3rd-party Django, they should be able to help you create Oracle client, server and Oracle Net trace files that may help identify the failing statement, or sequence of statements. I see a comment in the SR about what you've tried; work with them on the best way to handle this. See MOS Doc ID 203967.1 for client side tracing. The traces might identify the base issue.

I would also turn on DPI tracing by setting the environment variable DPI_DEBUG_LEVEL to 16. and seeing if this also identifies the failing statement.

If you can give us a pure cx_Oracle test case, then we (cx_Oracle dev) can take it to the relevant Oracle Development groups.

There was a big refactor in cx_Oracle 6, which would explains the behavior compared with 5.

Could you update the original comment answers and mention the Instant Client versions you've tried - I see the SR has more info. BTW, OCI is always 'thick'.

[danizen]

@cjbj, my DBAs said that Oracle's advice was that using the same connection in multiple processes was a bad idea. I played "OPTIONS": { 'threaded' True }. Later, I turned up the logging to verify there was only on pid/tid involved.

BTW, OCI is always 'thick'

That is odd. I assumed thin, because when I use PyCharm IDE from Home to a database server over VPN, choosing "Thick" doesn't work. But my python test cases do... I just assumed that only thin was used by cx_Oracle. I think instead that only thick is used by cx_Oracle.

[danizen]

@cjbj, Here is the DPI tracing file, which I will also pass on to Oracle support:

dpi-tracing.txt

[anthony-tuininga]

Please redo the logging, but with DPI_DEBUG_LEVEL set to 24. The value of 8 will highlight any errors and where those errors took place. It is possible that the error is taking place before the execution takes place, so the offending SQL is not logged.

[danizen]

@anthony-tuininga , attached is a SQL*Net client trace of the error with tracing level 16. Running with DPI_DEBUG_LEVEL set to 24 did not emit any additional output; possibly because we are still using cx_Oracle 6.4.1. I am working to update some internal software which needs to be updated so we can update to Django 2.2 (generally), so that we can try again with the latest cx_Oracle.

Attached below is a SQL*Net client trace with tracing level 16:
sqlnettrace.zip

[cjbj]

@danizen please work with Oracle Support on analyzing the SQL*Net trace. And also get a client trace, which is different. This is their area of expertise.

[danizen]

After upgrading some other libraries, I was finally able to upgrade to cx_Oracle 7.1.3, and can confirm that this problem does occur with the latest cx_Oracle. I still need to try the latest Oracle instantclient.

[cjbj]

@danizen thanks for the update. We still are relying on you and Support to identify any failing SQL, or other, statements.

[danizen]

@cjbj, I am uncertain how to proceed. In the worst case, you guys will need to educate me on how to run python and cx_Oracle and some python code through gdb.

I have the following thoughts:

• Start a new Django project without any of our code, but connected to the same schema. This allows us to run the Django code only and eliminates our code.

• Try the same code with a newly created Oracle schema - because Django's migrations, the very operation that detects this issue will also recreate the DDL for the application, and possibly reproduce the problem.

• Django has a "database wrapper" that wraps both the connection and cursor objects. Code the same SQL statements in a plain python file with just cx_Oracle, directed against the same schema. It may still be hard to reproduce the problem as we need to interact with the connection and cursor in the same manner.

• Should I look for common external symbols between cx_Oracle that may be provided by other extension modules we are using? How would I build cx_Oracle with debugging symbols provided? I am suspicious of DPI even though I understand that you wish to care about ORACLE_HOME and LD_LIBRARY_PATH at run time rather than build-time. My C knowledge is not dead, just sleeping ;)

• On Windows, try to get my code running under Visual Studio rather than PyCharm, so that I could potentially debug both the Python code and the C-code at the same time. Maybe try the same thing with gdb on CentOS - quite a challenge. Maybe one of these is something you guys can help me with.

[danizen]

Let me at least be clearer about where the problem is occurring. I see the root exception being thrown from line 497 of the file django/db/backends/oracle/base.py in Django 1.11.20, running the following query:

SELECT
  "DJANGO_CONTENT_TYPE"."ID",
  "DJANGO_CONTENT_TYPE"."APP_LABEL",
  "DJANGO_CONTENT_TYPE"."MODEL"
FROM "DJANGO_CONTENT_TYPE" 
WHERE "DJANGO_CONTENT_TYPE"."APP_LABEL" = :arg0

The parameters passed look like this from the python side:

{':arg0': 'auth'}

I also see that I was incorrect about the environment variables at the time of the error, because Django overrides some environment variables, and the Python debugger reports the following:

(Pdb) os.environ['NLS_LANG']
'.AL32UTF8'
(Pdb) os.environ['ORA_NCHAR_LITERAL_REPLACE']
'TRUE'

[cjbj]

I would start with your third point "Code the same SQL statements in a plain python file with just cx_Oracle". To get to that point you may need to do miscellaneous tracing (Oracle client, ODPI-C).

[danizen]

@cjbj , I will try that today. We have that dpi-tracing.txt file, which includes the generated error:

ODPI [14474] 2019-05-20 13:08:40.756: OCI error ORA-03124: two-task internal error (dpiStmt_execute / execute)

[danizen]

Here is a more complete DPI tracing log with DPI_DEBUG_LEVEL=63:

dpi-tracing-63.txt

I've also updated the file django/db/backends/oracle/base.py to log an error with the statement, params, and exception information when the issue occurs, and that output is also in the file.

This more complete tracing should allow me to mirror what Django is doing with the cursor after executing it and see if I can reproduce this with a single file python script.

[danizen]

Looking at src/dpiStmt.c, I do not see where dpiError_t error is initialized to 0.

In ISO/IEC 9899:TC3 WG14/N1256 (C99 standard) section 6.7.8 clause 10:

If an object that has automatic storage duration is not initialized explicitly, its value is indeterminate.

This might be a difference between Solaris and Linux in practice. Most of the time, this would not be an issue, because you check the return code and then return, but there may be a vulnerability somewhere here - maybe a place where you need to check for errno == EINTR and continue to wait on a socket or something.

I'm not so far grasping at straws that I'm setting it to zero and compiling it; it is just a thought.