Bug: DPY-5003: internal error: read a negative integer when expecting a positive integer

[idan-margalit]

Hi,
I am running dbt (data build tool) as a function in Oracle OCI.
Yesterday I pushed some new logic into one of my sql models and suddenly I get this very annoying bug:
"DPY-5003: internal error: read a negative integer when expecting a positive integer"
This stopped me from releasing data for a second day now and I'm going nuts.
I have no Idea what changed other than the addition of a new logic.
By the way, if I am taking my new logic into sql developer it runs ok and everything is fine..
This is just so frustrating.
Has anyone encountered this?

[anthony-tuininga]

This can occur if the data the server is sending is not understood by the client (or a bug in the client causes the client to be unsynchronized with the server). Which version are you using? Can you provide the full traceback? Can you also get this consistently and are you able to share the test case? I can take a look.

You can also try thick mode by enabling it.

[anthony-tuininga]

Thanks for the update! I will try with 15+ UNION ALL clauses and see if I can replicate the issue that way -- I'll let you know once I get a chance to do that testing.

[anthony-tuininga]

Ok. I tried with a simple select frion dual and 16 of these queries with a UNION ALL clause between them. I did not, unfortunately, see the problem. Do you see the problem with this script?

cursor = conn.cursor()
frags = [f"select {i + 1} as num, 'String {i + 1}' as str from dual" \
        for i in range(16)]
sql = " union all ".join(frags)
cursor.execute(sql)
for row in cursor:
    print(row)

I even bumped the number of union all clauses up to 500 and still didn't notice an issue, unfortunately. Are you able to share the SQL you are executing that is cause the problem?

[anthony-tuininga]

I just pushed a change that may correct this issue for you. If you are able to build from source you can verify that it corrects your issue. If so, please let me know! Thanks.

[idan-margalit]

Hi man
I have no idea what you did.
Maybe I can figure it out on my own but I couldn't locate it.
This error returned again on my project, and I used this incident to try and run it again after downloading the updated oracledb package.
Same code - only package version changed.
Aaaaand - IT WORKED!
So - this is great.
If you can elaborate on what you did that would be amazing and also interesting.

[anthony-tuininga]

The issue I found was corrected in this commit. I wasn't sure if it would resolve your situation but I am glad to hear that it did!

At issue is that the database can send back a negative error position under some circumstances. It is unknown what those circumstances are exactly but ensuring that the driver can accommodate negative values was the solution.

[hvbtup]

I had this error today with oracledb 2.5.0.
Will have to collect more detailed information.

File "D:\lisa_lims\lisa_import_service\python\tup\framework\watcher.py", line 609, in process_file_in_db
curs.execute(sql, **args_vars)
~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^
File "D:\lisa_lims\lisa_import_service.venv\Lib\site-packages\oracledb\cursor.py", line 710, in execute
impl.execute(self)
~~~~~~~~~~~~^^^^^^
File "src\oracledb\impl/thin/cursor.pyx", line 196, in oracledb.thin_impl.ThinCursorImpl.execute
File "src\oracledb\impl/thin/protocol.pyx", line 440, in oracledb.thin_impl.Protocol._process_single_message
File "src\oracledb\impl/thin/protocol.pyx", line 441, in oracledb.thin_impl.Protocol._process_single_message
File "src\oracledb\impl/thin/protocol.pyx", line 409, in oracledb.thin_impl.Protocol._process_message
File "src\oracledb\impl/thin/protocol.pyx", line 388, in oracledb.thin_impl.Protocol._process_message
File "src\oracledb\impl/thin/messages.pyx", line 2266, in oracledb.thin_impl.ExecuteMessage.process
File "src\oracledb\impl/thin/messages.pyx", line 336, in oracledb.thin_impl.Message.process
File "src\oracledb\impl/thin/messages.pyx", line 856, in oracledb.thin_impl.MessageWithData._process_message
File "src\oracledb\impl/thin/messages.pyx", line 937, in oracledb.thin_impl.MessageWithData._process_row_data
File "src\oracledb\impl/thin/messages.pyx", line 590, in oracledb.thin_impl.MessageWithData._process_column_data
File "src\oracledb\impl/thin/packet.pyx", line 494, in oracledb.thin_impl.ReadBuffer.read_lob_with_length
File "src\oracledb\impl/base/buffer.pyx", line 789, in oracledb.base_impl.Buffer.read_ub8
File "src\oracledb\impl/thin/packet.pyx", line 249, in oracledb.thin_impl.ReadBuffer._get_int_length_and_sign
File "D:\lisa_lims\lisa_import_service.venv\Lib\site-packages\oracledb\errors.py", line 195, in _raise_err
raise error.exc_type(error) from cause
oracledb.exceptions.InternalError: DPY-5003: internal error: read a negative integer when expecting a positive integer

[anthony-tuininga]

More information will definitely be needed! Please do try with the latest release (3.4.1) as well and if it replicates there, please supply a script that replicates the issue and I will be happy to look into it!

[hvbtup]

It's strange.
First, some background info: The program where the issue occurs in our case is a background program that watches a directory for new files, and if a new file is found, it is uploaded to the DB and processed there, using an inversion-of-control concept; when performing a stept in the DB, the DB tells the python program what step should be next, so this is very generic. In our case, the first step is CLOB_TO_DB (read the file as text using a specified encoding and upload it to the DB as a CLOB.

The upload is here (the variable names and messages are a mixture of German and English):

First, a function is called, which prepares which (packaged) stored procedure to call and with which args:

        offset = 0
        lobvar = curs.var(oracledb.CLOB)
        lob = self.conn.createlob(oracledb.CLOB)
        lobvar.setvalue(0, lob)
        rest = max_chars
        text_stream = io.TextIOWrapper(stream, encoding, newline)
        try:
            while rest:
                chunk = text_stream.read(min(1024*1024, rest))
                if not chunk:
                    break
                lob.write(chunk, offset+1)
                offset += len(chunk)
                rest -= len(chunk)
        finally:
            text_stream.detach()
            del text_stream
            stream.seek(0)
        proc = command
        args = OrderedDict([
            ("pi_clob", lobvar),
            ("pi_encoding", encoding),
            ("pi_linesep", Escape.char_to_db(linesep)),
        ])
        return (proc, args) # type: ignore

Next, the procedure is called. Since the variables can be different types, we need to preprocess them.

                
                args_sql = []
                args_vars = {}
                for name, wert in args.items():
                    if isinstance(wert, dict):
                        # Properties
                        txt = []
                        for indx, (key, val) in enumerate(wert.items()):
                            log.debug("%s=%s", key, val)
                            n = "%s_%d" % (name, indx)
                            txt.append("KeyValue('%s', :%s)" % (key, n))
                            args_vars[n] = val
                        args_sql.append("%s => %s.KeyValueTable_To_String_Props(KeyValueTable(%s))" % (name, ctx.package, ", ".join(txt)))
                    elif isinstance(wert, list):
                        # Es muss eine String-Liste sein
                        wert = [(v and str(v) or "") for v in wert]
                        args_vars[name] = curs.arrayvar(oracledb.STRING, wert)
                        args_sql.append("%s => :%s" % (name, name))
                    else:
                        if isinstance(wert, str):
                            v = wert
                        elif wert is None:
                            v = curs.var(oracledb.STRING)
                            v.setvalue(0, "")
                        elif isinstance(wert, int):
                            v = wert
                        elif isinstance(wert, float):
                            v = wert
                        elif isinstance(wert, bool):
                            v = wert
                        elif isinstance(wert, datetime.datetime):
                            v = wert
                        elif isinstance(wert, io.TextIOBase):
                            v = wert
                        elif isinstance(wert, io.TextIOBase):
                            v = curs.var(oracledb.CLOB)
                            v.setvalue(0, wert.read())
                        elif isinstance(wert, io.IOBase):
                            v = curs.var(oracledb.BLOB)
                            v.setvalue(0, wert.read())
                        elif isinstance(wert, oracledb.Var):
                            v = wert
                        else:
                            raise ValueError("Unbekannter Datentyp: %s", type(wert))
                        args_sql.append("%s => :%s" % (name, name))
                        args_vars[name] = v
                        del v  # Damit nicht versehentlich eine Referenz auf ein Lob übrig bleibt.
                sql = "BEGIN %s.%s(%s); %s.GET_AND_RESET_NEXT_STEP(:po_next_step); END;" %  (ctx.package, proc, ", ".join(args_sql), ctx.package)
                po_next_step = curs.var(oracledb.STRING)
                args_vars["po_next_step"] = po_next_step
                log.debug("sql=%s\nargs=%s", sql, args_vars)
                curs.execute(sql, **args_vars)
                next_step = po_next_step.getvalue()
                log.info("DB sagt next_step=%s", next_step)

Here, I just today noticed a bug: A duplicate elif condition for io.TextIOBase. But I think this doesn't matter, because our variable is a (LOB) variable.

The initial bug was reported last December, and we updated to oracledb 3.4.1 and this fixed the bug in the test system..
So we though: "Fine!"

Until we finally tried to update the production system today.
The bug - with the same traceback that I reported in December) seems to happen for every file we try to process (read: every CLOB to upload to the DB).

We compared the DB version and the Python and oracledb versions.
Everything seems identical in test and production:

Python 3.13.10, running in a venv environment on Windows, with oracledb 3.4.1 in thin mode (which is obvious from the traceback)

The DB is Oracle Standard Edition 2 19.9.0.0.0

One difference was that the TEST system has a sqlnet.ora with sqlnet.authentication = (None) while the PROD system doesn't have a sqlnet.ora. But this doesn't make a difference: We renamed that file for the TEST system and tested again, and the result stays the same:

• It works in the TEST system.
• I doesn't work in the PROD system.

[hvbtup]

One thing that is somewhat special in our case, and may be relevant:
This IOC pattern is inside a loop. The cursor is created before the loop and reused in the loop:

        curs = self.conn.cursor()
        try:
            while True:
                # See the code above
                assert isinstance(next_step, str)
                ergebnis = next_step.split()[0]
                if ergebnis not in CONTROL_COMMANDS + STANDARD_CLIENT_COMMANDS:
                    ...
                if ergebnis in ["OK", "ERROR", "RETRY"]:
                    ...
                    break
                else:
                    try:
                        (proc, args) = getattr(self, "do_" + ergebnis)(ctx, next_step, curs)
                    except:
                        ...
        finally:
            try:
                curs.close()
            except:
                ...

I could try to create a new cursor for each call.

[hvbtup]

I think this issue should be reopened.

[hvbtup]

Is DPY-5003 more or less the same as ORA-03120?

I had a similar error in a different application using Oracledb in thick mode with Instantclient 23.6 and Oracle DB 19.25.

In that other case, I was using
INSERT ... EMPTY_BLOB() ... RETURNING blob_column INTO ...

And the workaround was to use two steps instead:

1. INSERT
2. SELECT blob_column FOR UPDATE

Unfortunately, I cannot use this workaround here, because here, I don't update a LOB column in a table, but I supply the LOB to a PL/SQL stored procedure, for the CLOB case with this signature:

   /** Wird vom CP aufgerufen, um ein CLOB hochzuladen..
    *
    *  @PARAM pi_clob      Clob (Das CLOB wird meist temporär sein, ans Aufräumen denken.)
    *  @PARAM pi_encoding  Das verwendete Encoding
    *  @PARAM pi_linesep   Falls Zeilenenden konvertiert wurden, wie?
    *
    *  @AUTHOR hvb
    *  @SINCE  09.09.2022
    */
    PROCEDURE CLOB_TO_DB
    ( pi_clob in out nocopy clob -- Das CLOB wird meist temporär sein, ans Aufräumen denken.
    , pi_encoding in varchar2     -- Das verwendete Encoding
    , pi_linesep in varchar2     -- Falls Zeilenenden konvertiert wurden, wie?
    );

[hvbtup]

Today I tested the idea to create a new cursor for each call.
Unfortunately, this didn't change anything, still DPY-5003.

[anthony-tuininga]

If you are able to get this to happen consistently, please set the environment variable PYO_DEBUG_PACKETS to any value and then run the script, capturing the output to a file. Then e-mail me the file (assuming it is small enough to do so) and I will take a look.