Unmanaged Oracle.DataAccess does not support empty CLOBs

[poke]

Hey, we’re having a problem with the unmanaged Oracle.DataAccess version 4.122.21.1, which is the currently the latest from the Oracle website.

We are using this to access data that is being written with Oracle.EntityFrameworkCore. For some reason, which surprises me to be honest, the managed Oracle.ManagedDataAccess (which is used by EF) is able to read and write both null and empty strings as distinct values in a CLOB column. I was under the impression before that this would both be set to NULL inside of the Oracle database.

Anyway, so far so good, we can live with that just fine. However, it seems that the unmanaged Oracle.DataAccess is not able to work with an empty string in a CLOB column.

For this purpose I set up the following test to reproduce this:

using (var db = new ExampleContext(dbContextOptions))
{
    try { db.Database.ExecuteSqlRaw("DROP TABLE TEST"); } catch { }
    db.Database.ExecuteSqlRaw("CREATE TABLE TEST(ID NUMBER(19), VALUE CLOB)");

    db.Set<Entity>().Add(new Entity
    {
        Id = 1,
        Value = "", // <-- this is where the empty string is
    });
    db.SaveChanges();
}

Console.WriteLine("Access via EF Core");
using (var db = new ExampleContext(dbContextOptions))
{
    var item = db.Set<Entity>().Find(1);
    Console.WriteLine("  Item has value: {0}", item.Value is null ? "null" : $"'{item.Value}'");
}

Console.WriteLine("Access via DataTable on Oracle.ManagedDataAccess:");
using (var connection = new OracleConnection(ConnectionString))
{
    connection.Open();
    var query = "SELECT ID, VALUE FROM TEST";
    var adapter = new OracleDataAdapter(query, connection);
    var dataTable = new DataTable();
    adapter.Fill(dataTable);

    var value = dataTable.Rows[0].Field<string>("VALUE");
    Console.WriteLine("  Item has value: {0}", value is null ? "null" : $"'{value}'");
}

This will first create a table TEST with a CLOB column and then insert an item with an empty string as the value. It will then try to read out the value using EF again and then using Oracle.ManagedDataAcccess which both work just fine:

Access via EF Core
  Item has value: ''
Access via DataTable on Oracle.ManagedDataAccess:
  Item has value: ''

Afterwards, I try the same thing with the unmanaged Oracle.DataAccess on .NET Framework:

Console.WriteLine("Access via DataTable on Oracle.ManagedDataAccess:");
using (var connection = new OracleConnection(ConnectionString))
{
    connection.Open();
    var query = "SELECT ID, VALUE FROM TEST";
    var adapter = new OracleDataAdapter(query, connection);
    var dataTable = new DataTable();
    adapter.Fill(dataTable);

    var value = dataTable.Rows[0].Field<string>("VALUE");
    Console.WriteLine("  Item has value: {0}", value is null ? "null" : $"'{value}'");
}

Here, the execution will stay on the adapter.Fill(dataTable) line, seemingly never finishing.

According to a collegue, this is working on Oracle.DataAccess 19c. So the issue appears with Oracle.DataAccess 21c. We have been testing this with Oracle 19c databases (both standard and XE editions).

I’ve set up a repository ready to be played with. You just need to have the Oracle.DataAccess 21c installed on your machine in order for this to work.

[alexkeh]

@poke That's really unusual that if there was an error, that no exception was thrown. Can you turn on unmanaged ODP.NET tracing and client side SQL Net trace. You can add the following to your .NET config file

<configuration>
<oracle.dataaccess.client>
    <settings>
      <add name="TraceFileName"         value="c:\traces\odpnet.trc"/>
      <add name="TraceLevel"            value="255"/>
    </settings>
  </oracle.dataaccess.client>
</configuration>

To turn on SQL Net tracing, you can add the following to your local sqlnet.ora.

TRACE_LEVEL_CLIENT = 16
TRACE_FILE_CLIENT = odp.trc
TRACE_DIRECTORY_CLIENT = Set full path where to save trace. Make sure the directory has read and write permissions for the user
TRACE_TIMESTAMP_CLIENT = ON
TRACE_FILELEN_CLIENT=100000
TRACE_FILENO_CLIENT=1
DIAG_ADR_ENABLED=OFF
TRACE_UNIQUE_CLIENT=ON

I expect you only need to run your unmanaged ODP.NET app that fills the DataSet.

It's possible that there is a problem on the DB server side and these traces won't capture that. However, let's begin debugging on the client side first.

[poke]

@alexkeh Thank you for your quick response! For what it’s worth, we have tested this on three different Oracle 19 database instances (2 standard, 1 XE) and with 3 different clients (one Windows Server 2019, two Windows 11 devices). We can replicate this whenever using the unmanaged 21c driver targeting the Oracle 19 machine.

I’ve tried the tracing now, though I am not sure if I did the sqlnet.ora-one correctly since I didn’t get any output (I configured this both on the client and on the database server; or at least I tried). For the odpnet.trc, the file ends with the following lines:

TIME:2024/03/01-12:50:23:894 TID:c908  (ENTRY) OracleConnection::RegisterForConnectionClose()
TIME:2024/03/01-12:50:23:894 TID:c908  (EXIT) OracleConnection::RegisterForConnectionClose()
TIME:2024/03/01-12:50:23:924 TID:c908  (ENTRY) OracleDataReader::GetName()
TIME:2024/03/01-12:50:23:924 TID:c908  (EXIT)  OracleDataReader::GetName()
TIME:2024/03/01-12:50:23:924 TID:c908  (ENTRY) OracleDataReader::GetName()
TIME:2024/03/01-12:50:23:924 TID:c908  (EXIT)  OracleDataReader::GetName()
TIME:2024/03/01-12:50:23:928 TID:c908  (ENTRY) OracleDataReader::GetFieldType()
TIME:2024/03/01-12:50:23:928 TID:c908  (EXIT)  OracleDataReader::GetFieldType()
TIME:2024/03/01-12:50:23:928 TID:c908  (ENTRY) OracleDataReader::GetFieldType()
TIME:2024/03/01-12:50:23:928 TID:c908  (EXIT)  OracleDataReader::GetFieldType()
TIME:2024/03/01-12:50:23:936 TID:c908  (ENTRY) OracleDataReader::Read()
TIME:2024/03/01-12:50:23:936 TID:c908  (ENTRY) OpsDacRead(): (70e55810)=1894078480

Followed by repeated blocks of the following that just appear to be some periodic cleanup (every 3 minutes), unrelated to the current exection:

TIME:2024/03/01-12:53:23:755 TID:c738  (ENTRY) CPCtx:RegulateNumOfConsThreadFunc()
TIME:2024/03/01-12:53:23:773 TID:c738 (ENTRY) ConnectionPool.RegulateNumOfCons()
TIME:2024/03/01-12:53:23:773 TID:c738  (EXIT) ConnectionPool.RegulateNumOfCons()
TIME:2024/03/01-12:53:23:773 TID:c738  (EXIT)  CPCtx:RegulateNumOfConsThreadFunc()

The logs stopping on the OpsDacRead makes sense to me considering that the reading isn’t able to stop, and since there is also not an error even if you keep the application running for a while.

I’ve also repeated this a few times and the logs look mostly the same. I have attached the full trace file of my latest run here in case you want to take a look.

Let me know where I can try to look next on the database side in an attempt to find out more. Alternatively, you can of course also try to run the example projects yourself. It should be relatively quick to set up if you have an Oracle database lying around somewhere.

Oh, and one more thing which I maybe didn’t make clear before: If you change the line Value = "" to insert the data with any other value (including null), then accessing the value from the unmanaged library works just fine. It’s just the empty string that causing this issue here.

[alexkeh]

@poke I tested your unmanaged ODP.NET code with unmanaged ODP.NET 21.12 and 19c DB, If I insert an empty CLOB, INSERT INTO TEST VALUES(2, empty_clob());

I get the result Item has value: ''

If I insert no value between quotes. INSERT INTO TEST VALUES(1, '');

I get the result Item has value: null

I am not able to reproduce your behavior.

In your trace, I see a Read() call entry, but no exit occurs. This should occur when the operation is completed. I'll run the trace by my dev team to see if there's anything of note. My guess is to run a DB server trace to understand whether it's returning the result. If not, then what is it getting stuck on.

[poke]

@alexkeh That is super weird that this problem does not appear on your side.

I’ve tried it with the INSERT INTO TEST VALUES(1, empty_clob()) and that still makes the problem appear for me, so I should be able to reduce my repro setup to avoid the managed part. I’ll try to find some time tomorrow to simplify it further, so that I can try it out on few more different machines to see if I can get this reproduced deterministically.

In your trace, I see a Read() call entry, but no exit occurs. This should occur when the operation is completed.

Yeah, and that matches what I am seeing that the process simply never completes but just appears to halt on the read forever.

My guess is to run a DB server trace to understand whether it's returning the result.

Do you have some resource I could read for how to do that? I’ve tried an ALTER SYSTEM SET trace_enabled = true and then checked the /opt/oracle/diag/rdbms/xe/XE/trace/ for new files but the only files that were updated during my test didn’t contain any information on the test, so I’m probably doing it wrong.

[alexkeh]

@poke To turn on DB server net tracing, you make the following changes to your DB's sqlnet.ora file, then bounce your DB for the settings to take effect.

TRACE_LEVEL_SERVER = 16
TRACE_FILE_SERVER = server
TRACE_DIRECTORY_SERVER = Set full path where to save trace. Make sure the directory has read and write permissions for the user
TRACE_TIMESTAMP_SERVER = ON
TRACE_FILELEN_SERVER=100000
TRACE_FILENO_SERVER=10
DIAG_ADR_ENABLED=OFF

I heard back from one of my dev team members. It appears we're getting stuck on the underlying Oracle Call Interface layer in the fetch stage. The client side SQL Net trace would need to be looked at there, though you mentioned you had trouble getting that working.

Note you can't use the SQL Net client and server trace settings interchangeably as they have different names (e.g. TRACE_LEVEL_SERVER vs. TRACE_LEVEL_CLIENT).

[poke]

@alexkeh I was able to produce server-side trace files, though I am not sure if they contain any useful information. I could see a part where the select is being written, and then there is some data block that looks like a response, followed by another block where it said something about “ORA-01403 no data found” though I am not sure if that’s still part of the response or not.

Can I send you the files per email or somewhere else? I don’t really want to attach them here in the open since they contain some level of sensitive information.

As for the client side logging, I cannot get the sqlnet.ora trace to work. I tried creating the file at the correct location ORAHOME\network\admin\sqlnet.ora (that’s the Oracle home directory that I created when installing the unmanaged driver using the xcopy ODAC package) but I am not sure if this is really picked up. Does the sqlnet.ora actually apply to the .NET drivers? Aren’t those unrelated to the Oracle home directory (except for the DllPath configuration which looks there for the additional dlls)? Or is there a way to tell (maybe at runtime) at what locations it looks like for an sqlnet.ora?

[alexkeh]

@poke You can email the trace to us at dotnet_us(at)oracle.com.

sqlnet.ora applies to ODP.NET. What may be happening is that you have another sqlnet.ora on your machine and that one is getting loaded before the one in your ORAHOME\network\admin\ directory.

To tell at runtime which sqlnet.ora is loaded requires the sqlnet trace. But you can't enable that trace since you don't know which one is loaded. You can use Sysinternals Process Explorer from MS to see which sqlnet.ora is being loaded. Just make sure to filter for only sqlnet.ora as Process Explorer will start writing every file Windows is loading and it will difficult to find sqlnet.ora in the long list.

With that said, we can start with the server side trace as it appears the Read request is received.

[alexkeh]

Closing this for now as we haven't received a trace file to further investigate. I will reopen after receiving the trace.