Stange issue I cannot resolve where the field and values in the returned DataReader are from the previous query

[phkendall]

I'm sure if this is the correct place to submit this issue, but here goes anyway.

I have been using PetaPoco in a heavily used ASP.NET production system since October 2012. We run in a .net 2.0 runtime, compiled with the flag PETAPOCO_NO_DYNAMIC. Everything has been working great until about a week ago, when after no changes to the code, we started getting strange exceptions in the PetaPoco code. These exceptions only occur after a number of hours of usage on busy days. Recycling the IIS application pool cures the problem for a few hours (up to 10 or 15), but then if the server remains heavily used the problem will come back. Here is an example exception:

System.InvalidCastException: Unable to cast object of type 'System.Int32' to type 'System.String'.
at System.Data.SqlClient.SqlBuffer.get_String()
at petapoco_factory_0(IDataReader )
at petapoco_multipoco_factory(MultiPocoFactory , IDataReader , Object )
at PetaPoco.Database.<Query>d__1a1.MoveNext() at System.Linq.Enumerable.FirstOrDefault[TSource](IEnumerable1 source)
at XXX.XXX.SplitData.Repositories.PostAllocationTaskRepository.Get(String jobPlanId)

To help diagnose the problem I placed some trace output into the PetaPoco.Database.Query<TRet>(Type[] types, object cb, string sql, params object[] args) method like so:

TRet poco; try { if (!r.Read()) break; poco = factory(r, cb); } catch (Exception x) { System.Diagnostics.Trace.WriteLine(string.Format("## Query ##")); System.Diagnostics.Trace.Indent();

                            System.Diagnostics.Trace.WriteLine(string.Format("SQL: '{0}'", sql));

                            Object[] values = new Object[r.FieldCount];
                            int fieldCount = r.GetValues(values);
     for (int i = 0; i < fieldCount; i++)
     {
                                System.Diagnostics.Trace.WriteLine(string.Format("Reader Value: '{0}', '{1}'", i, values[i]));
    }
                            foreach (var arg in args)
                            {
                                System.Diagnostics.Trace.WriteLine(string.Format("ARGS: '{0}'", arg));
                            }
                            System.Diagnostics.Trace.WriteLine(string.Format("Culture: {0}", Thread.CurrentThread.CurrentCulture.Name));
                            System.Diagnostics.Trace.WriteLine(string.Format("Culture Decimal Separator: {0}", Thread.CurrentThread.CurrentCulture.NumberFormat.NumberDecimalSeparator));
                            System.Diagnostics.Trace.WriteLine(string.Format("Culture Positive sign: {0}", Thread.CurrentThread.CurrentCulture.NumberFormat.PositiveSign));
                            System.Diagnostics.Trace.Unindent();

                            OnException(x);
                            throw;

}

Below is the trace output from two consecutive queries (the first query caused the exception above):

00832529 12:02:09 [10688] ## Query ##
00832530 12:02:09 [10688]
00832531 12:02:09 [10688] SQL: 'SELECT PostAllocationTasks., PostAllocationTaskStatuses.
00832532 12:02:09 [10688] FROM dbo.PostAllocationTasks
00832533 12:02:09 [10688] INNER JOIN dbo.PostAllocationTaskStatuses
00832534 12:02:09 [10688] ON PostAllocationTasks.StatusId = PostAllocationTaskStatuses.Id 00832535 12:02:09 [10688] WHERE (JobPlanId = @0)'
00832536 12:02:09 [10688]
00832537 12:02:09 [10688] Reader Value: '0', '1'
00832538 12:02:09 [10688]
00832539 12:02:09 [10688] ARGS: 'IP1008197'
00832540 12:02:09 [10688]
00832541 12:02:09 [10688] Culture: en-GB
00832542 12:02:09 [10688]
00832543 12:02:09 [10688] Culture Decimal Separator: .
00832544 12:02:09 [10688]
00832545 12:02:09 [10688] Culture Positive sign: +

00832546 12:02:11 [10688] ## Query ##
00832547 12:02:11 [10688]
00832548 12:02:11 [10688] SQL: 'SELECT JobFinancialsView., RateCodesView.
00832549 12:02:11 [10688] FROM JobFinancialsView
00832550 12:02:11 [10688] INNER JOIN RateCodesView
00832551 12:02:11 [10688] ON JobFinancialsView.RateCode = RateCodesView.Id
00832552 12:02:11 [10688] WHERE (JobId = @0)
00832553 12:02:11 [10688] ORDER BY OrderIndex, RateCode'
00832554 12:02:11 [10688]
00832555 12:02:11 [10688] Reader Value: '0', 'IP1008197'
00832556 12:02:11 [10688]
00832557 12:02:11 [10688] Reader Value: '1', '19/02/2013 11:54:06'
00832558 12:02:11 [10688]
00832559 12:02:11 [10688] Reader Value: '2', '19/02/2013 11:54:15'
00832560 12:02:11 [10688]
00832561 12:02:11 [10688] Reader Value: '3', '19/02/2013 11:55:46'
00832562 12:02:11 [10688]
00832563 12:02:11 [10688] Reader Value: '4', '2'
00832564 12:02:11 [10688]
00832565 12:02:11 [10688] Reader Value: '5', '0.60'
00832566 12:02:11 [10688]
00832567 12:02:11 [10688] Reader Value: '6', 'A critical error occured. The error has been logged, please contact your system administrator.'
00832568 12:02:11 [10688]
00832569 12:02:11 [10688] Reader Value: '7', '2'
00832570 12:02:11 [10688]
00832571 12:02:11 [10688] Reader Value: '8', 'Failed'
00832572 12:02:11 [10688]
00832573 12:02:11 [10688] ARGS: 'J09734'
00832574 12:02:11 [10688]
00832575 12:02:11 [10688] Culture: en-GB
00832576 12:02:11 [10688]
00832577 12:02:11 [10688] Culture Decimal Separator: .
00832578 12:02:11 [10688]
00832579 12:02:11 [10688] Culture Positive sign: +

The odd thing I cannot work out is looking at the trace output, the reader values in the second query are the results from the first query. To me it appears that the previous reader is being used by the query, however I cannot understand how that could possibly happen.

Has anyone else experienced anything like this and can help me shed some light on it?

Thanks in advance

[ensecoz]

I also found strange issues during upload new assemblies to the production server (it might be the same if the IIS start recycle the AppPool). When I call function Save() on PetaPoco, it is resolving the properties of the class incorrectly (e.g. PetaPoco included the property of other class).

Sometime, it query the wrong result. (after uploading the new assemblies to the server again)

Different upload, produce different problems.

I believe this is happening on the busy site and it cause the concurrency issues in the PetaPoco.

I still not sure why it is happening.

One clue is that, I think it might be because of the internal caching mechanism of the PetaPoco itself not Thread-safe (I have to look more into the detail)

If anyone know how to resolve the issue, please suggest me.

Thanks,

[Shazwazza]

I'm also randomly getting this error as well but we've been using PetaPoco extensively for a long time now and this is the first I've seen it. Any chance you found a solution?

[BobT2022]

Bizarrely I'm also getting this issue sporadically and when calling a s/procedure to return a single record to hydrate an ORM domain model type.

I'm using PetaPoco v6.0.524 and Microsoft.Data.SqlClient v5.0.0 via a derived SqlServerDatabaseProvider class that allows me to override the GetFactory() method (and hence to use Microsoft.Data.SqlClient v5.0.0 rather than the standard System.Data.SqlClient v4.0.0 assembly).

I'm using .NET 5 and the following internal diagnostic trace log (of which includes a custom PetaPocoLoggingEventHandlers type to handle PetaPoco events, and a IUnitOfWork type that acts as a transactional wrapper around the PetaPoco Database instance).

This bug is really bizarre in that calling my REST API function in question (which calls the code stack below) works 99.99% of the time, but then presents the following "Unable to cast error" 0.01% of the time (the % representation may be exaggerated but literally seems that infrequent). Each API function call creates a new PetaPoco instance (and thus a new Database instance, and correspondingly a new DB connection), and no DB transaction applies (since I'm reading logical record locking state info. only).

I can't however replicate the issue in code as I can't see what the natural trigger for the exception would be, given that running the SQL in question (a s/proc taking two parameters and returning a single data row [all redacted] works 100% of the time as expected, returning the correct data columns with the correct data types).

Just to add the REST API is running over Kestrel as a self-hosted Windows Service application, not IIS.

2022-09-14T11:08:35.6072195+01:00 0HMKM72GH6DQ6:00000002 [ERR] The database operation failed due to an exception running the command [dbo.****
	 -> @0 [String] = "***"
	 -> @1 [String] = "***"] against DB [****]: Unable to cast object of type 'System.DateTime' to type 'System.Int32'. [Thread ID: 14] [Inner Exception: n/a] (2ae7b9a2)
2022-09-14T11:08:35.6076036+01:00 0HMKM72GH6DQ6:00000002 [VRB] Connection Closed for [****]. KeepConnectionAlive: [False] [Thread ID: 14] (f335d909)
2022-09-14T11:08:35.6281479+01:00 0HMKM72GH6DQ6:00000002 [ERR] Unable to cast object of type 'System.DateTime' to type 'System.Int32'.
   at Microsoft.Data.SqlClient.SqlBuffer.get_Int32()
   at petapoco_factory_0(IDataReader )
   at PetaPoco.Database.ExecuteReaderAsync[T](Action`1 processPoco, CancellationToken cancellationToken, CommandType commandType, String sql, Object[] args)
   at ****.PetaPocoLoggingEventHandlers.OnExceptionThrown(Object sender, ExceptionEventArgs e)
   at PetaPoco.Database.OnException(Exception x)
   at PetaPoco.Database.ExecuteReaderAsync[T](Action`1 processPoco, CancellationToken cancellationToken, CommandType commandType, String sql, Object[] args)
   at PetaPoco.Database.FetchProcAsync[T](CancellationToken cancellationToken, String storedProcedureName, Object[] args)
   at ****.GetObjectLockStatus(IUnitOfWork unitOfWork, String sourceRef, String sourceObjectClass, CancellationToken cancellationToken)
   at ****.ObjectLockingController.GetObjectLockStatus(String sourceRef, String sourceObjectClass, CancellationToken cancellationToken)
   at lambda_method653(Closure , Object )
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.AwaitableObjectResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Awaited|12_0(ControllerActionInvoker invoker, ValueTask`1 actionResultValueTask)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeInnerFilterAsync>g__Awaited|13_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeNextExceptionFilterAsync>g__Awaited|25_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted) (6dc15af5)

More info: When I get the above error it appears that the number of columns (countColumns) passed into the GetFactory method of PocoData.cs is sometimes 1x less than the actual column count (6x columns in my case, meaning I get the issue when countColumns reads 5):

This has a knock-on consequence of the srcType and dstType (dstType specifically) becoming mis-matched, in that for my specific example the 6th DB column in the result set is a NULLable SQL DATETIME value, which maps to my Poco model property that's declared as a nullable DateTime? type.

However, in the above the srcType is DateTime (correct) but dstType is an Int32 - that is, the type of the preceding Poco model property (which is an Int32).

Very strange behaviour, and completely unpredictable in terms of replication - so much so that I've commented out the part of the Cache Get method (Cache.cs) which retrieves the factory from the private Dictionary<TKey, TValue> _map collection (so as to build a factory [DynamicMethod delegate] each time, hoping to reproduce the error more frequently [still without success however, despite calling my function many thousands of times concurrently in a test script]).

[BobT2022]

Does look like https://github.com/CollaboratingPlatypus/PetaPoco/pull/129 needs to be done as https://stackoverflow.com/a/19664437/2270895 points out the issue using ReaderWriterLockSlim with async/await (which in my case I am using extensively).

Not quite sure where to go from here as I'd rather not make my large code base work synchronously and whilst a sporadic issue remains nonetheless a significant issue for us.

@pleb Sorry to ask, I know removing the Homemade Cache class is already on the roadmap for v6.5 (https://github.com/CollaboratingPlatypus/PetaPoco/wiki/Roadmap) but is it due anytime soon please? Thanks.

[pleb]

@BobT2022 I'm a little busy that the moment. Any chance you could do the work and submit a PR?

[asherber]

I'm not sure whether this will fix the hard-to-reproduce reported issue, but #655 (borrowing from @jpshannon) achieves the goal of replacing the Dictionary/ReaderWriterLockSlim in the Cache class.

[pleb]

Released and is a part of the https://www.nuget.org/packages/PetaPoco.Compiled/6.0.530-beta and https://www.nuget.org/packages/PetaPoco.Compiled/6.0.532 packages

[pleb]

@BobT2022 let us know how you go with the changes ;)

[BobT2022]

@pleb @asherber Very much appreciated, I know you're both extremely busy! I'll let you know :)

[BobT2022]

I've good news in that I believe I've found the problem, albeit ironically it seems to not be an issue with PetaPoco as far as I can see.

To explain:

After updating my implementation code to use the PetaPoco 6.0.532 package version kindly provided above, I was still observing the issue albeit still sporadically (i.e., < 0.01% of the time in over 50,000 invocations of my library code). As a sanity check I even changed my methods under test to be synchronous to rule out any lingering problems with async/await use; however, the same issue persisted.

So I looked at the data source (a s/proc) which is designed to return information about a business process lock held against a source data record. This s/proc returns null values for certain columns where no business process lock has been acquired (who owns the lock [an integer column] and when was the lock established [a date/time column]).

However it appears that calling GetSchemaTable on the IDataReader (to determine the data type of the destination property with the innards of the PetaPoco dynamic factory function [DynamicMethod] that converts a IDataReader record into a POCO object) returns an Int data type for any column value that is NULL.

Thus the issue suggests less to do with the PetaPoco Cache implementation (although the above package version does remove a long standing to-do item anyway) but more with the behaviour of the IDataReader GetSchemaTable within the Microsoft SqlClient implementation, which seems to be using a default field type (int) where the DB column value presented to it is null.

Not entirely sure whether this behaviour is documented (by Microsoft) but I couldn't see anything obvious.

In my specific case the fix (subject to further deployment testing in situ) hopefully should be a matter of forcing a CAST around NULL values returned from the DB - thus enforcing the data types in use.

A simple console application which selects two columns (LOCKED_BY and LOCKED_AT) using straight NULL values illustrates the behaviour of GetSchemaTable returning the .NET int data types for both columns:

    static void Main(string[] args)
    {
      using SqlConnection conn = new();
      conn.ConnectionString =  "<...>";

      string sql = "SELECT NULL AS LOCKED_BY, NULL AS LOCKED_AT;"; //NOT working OK
      //string sql = "SELECT CAST(NULL AS INT) AS LOCKED_BY, CAST(NULL AS DATETIME) AS LOCKED_AT;"; //Working OK

      conn.Open();
      using SqlCommand cmd = new(sql, conn);
      cmd.CommandType = CommandType.Text;
      SqlDataReader reader = cmd.ExecuteReader();
      DataTable schema = reader.GetSchemaTable();

      foreach (DataRow row in schema.Rows)
      {
        Console.WriteLine($"ColumnName: {row.Field<string>("ColumnName")} ::: NET Type: {row.Field<string>("DataTypeName")}");
      }

      reader.Close();
      conn.Close();

      Console.WriteLine("Press ENTER to finish");
      Console.ReadLine();
    }

Running this example as-is produces the following output, note the .NET Type for "LOCKED_AT" is showing incorrectly (per my expectations in code) as an integer:

Running the console application using the SQL having CASTs around the NULL column values seems to work OK in that the "LOCKED_AT" column type now shows as .NET DateTime as I'd expect:

As such I believe the inclusion of the CASTs around NULL column values are imperative, at least in my specific case.

This doesn't answer any questions as to phkendall's original description of the problem; however, that may indeed be resolved by the change in the Cache implementation (per PetaPoco v6.0.532), which incidentally I'll continue to use going forward.

I hope this has helped someone, and again thank you @pleb and @asherber for your valued assistance!

(p.s., I'll post any follow-up issues if they occur [hopefully not!]).

[asherber]

Thanks for the detailed info, but I'm currently not able to reproduce this with PetaPoco. Here's the LinqPad code I'm using:

void Main()
{
    var connString = "...";
   
    using (var db = new Database(connString, "Microsoft.Data.SqlClient"))
    {
        string sql = "SELECT NULL AS LOCKED_BY, NULL AS LOCKED_AT;";
        db.Fetch<Foo>(sql).Dump();
    }
}

public class Foo
{
    public string Locked_By { get; set; }
    public DateTime? Locked_At { get; set; }
}

As I would expect, this gives me:

When I run your code from above, I get the same results as you. This implies to me that PetaPoco knows how to do the right thing here, turning those null ints into the correct type on the target type.

What do you get when you run my code?

[BobT2022]

Hi @asherber, can't use LinqPad but a console app shows effectively the same thing:

Interestingly this SO post https://stackoverflow.com/questions/73296995/sqldatareader-getschematable-returns-data-type-int-when-all-values-are-null reports "...The default data type of NULL returned by SQL Server is int..." which is highly suggestive of the underlying issue at the heart of the problem.

In my case the s/proc is returning a row but because there's no values for the locked by / locked at columns, and despite adding an explicit CAST(NULL AS DATETIME) around the Locked At column (to denote no lock exists yet the column value should be handled per its DateTime? property POCO declaration) the issue remains.

I have refactored my code such that the s/proc returns no record at all to denote no lock exists, so having the underlying code handle the creation of the POCO manually (leaving the Locked By and Locked At properties to their default null values).

Thanks.

[asherber]

@BobT2022 I guess I'm wondering if you have correctly diagnosed the issue. Your previous comment implied that the problem was Sql Server returning an int type of null. But as my code shows (and your console app confirms), PP has no problems turning that null int into a null DateTime.

Are you able to provide a minimal example in C# that uses PP and demonstrates the problem?

[BobT2022]

@asherber It's more than likely I've missed something as other such code where null column values are mapped to nullable POCO properties seem to be Ok. I'll try and create a simple repro as soon as I can. Thanks for your help, much appreciated :)

[BobT2022]

@asherber Quick update - can't seem to replicate outside my wider application code, so I'll try and repro this issue as and when I can in the background. Thanks for the effort on the Cache class change though, much appreciated.