Devart Forums

bmarotta

While changing from OCI to DirectMode, we get the error "ORA-01483: invalid length for DATE or NUMBER" in one of our updates:

UPDATE PUMA_WORKFLOW_EXECUTION SET STATUS_ID = :p1, PROCESSING_SERVER = :p2 WHERE ID = :key1 AND STATUS_ID = :chk1 AND ((:nullchk2 = 1 AND PROCESSING_SERVER IS NULL) OR (PROCESSING_SERVER = :chk2))
-- p1: Input Number (Size = 0; DbType = Decimal) [2]
-- p2: Input NVarChar (Size = 36; DbType = String) [1c593409-991c-4fe5-b787-6bb10b6df9ae]
-- key1: Input Number (Size = 0; DbType = Decimal) [122336]
-- chk1: Input Number (Size = 0; DbType = Decimal) [1]
-- nullchk2: Input Integer (Size = 0; DbType = Int32) [1]
-- chk2: Input NVarChar (Size = 0; DbType = String) []
-- Context: Devart.Data.Oracle.Linq.Provider.OracleDataProvider Model: am Build: 1.0.43.0

This is the table creation SQL:

-- Create table
create table PUMA_WORKFLOW_EXECUTION
(
ID NUMBER(9) not null,
WORKFLOW_INSTANCE_ID NUMBER(9),
STATE_SEQUENCE NUMBER(9),
TASK_SEQUENCE NUMBER(9),
ACTION_SEQUENCE NUMBER(9),
STATUS_ID NUMBER(9) not null,
FINISHED NUMBER(1) default 0 not null,
COMMENTS NVARCHAR2(4000),
PROCESSING_SERVER NVARCHAR2(50),
MODIFICATION_DATE TIMESTAMP(6),
WORKFLOW_ID NUMBER(9) not null,
PRODUCT_ID NUMBER(9),
STATEFUL_OBJECT_ID NUMBER(9),
CHILD_PRODUCT_ID NUMBER(9),
PREDECESSOR_ID NUMBER(9),
PARENT_ID NUMBER(9),
RETRY_COUNT NUMBER(9) default 0 not null,
SOPHIS_USER_ID NUMBER(9)
);

Regards,

bmarotta

Hi Stanislav,

yes I meant:

Code: Select all

context.Transaction = context.Connection.BeginTransaction();

There is nothing special about our context handling. We have only one context per thread (this for sure). It is always started with an using clause

Code: Select all

using (var context = new DataContext())

By multithreading I just meant that our application, being a service provider, launch one query per thread. And I guess it is your connection pooling which is messing with things.

Also, the "do something" and "do another thing" can be really multiple calls to multiple statements doing a lot of things and maybe doing more than two SubmitChanges

This error does not happen all the time. It happens from time to time.

bmarotta

Hi,

today I've tried the Db Monitor with no special results. I see the statements in the log, but no special reason for it to hang

LOG

2011-01-18 19:04:24,855 INFO [PumaRobot2-2011-01-18 07:00:25.6579=>()] IssuanceEngine.Data.PumaDataContext Disconnect: Description: Close connection - Extra info:
2011-01-18 19:04:24,855 INFO [PumaRobot3-2011-01-18 07:00:45.5162=>()] IssuanceEngine.Data.PumaDataContext Disconnect: Description: Close connection - Extra info:
2011-01-18 19:04:24,855 INFO [PumaRobot2-2011-01-18 07:00:25.6579=>()] IssuanceEngine.Data.PumaDataContext Prepare: Description: Prepare: SELECT t2.ID, t2.WORKFLOW_ID, t2.TASK_ID, t2.TYPE AS "TYPE", t2.PROPRITY, t2.RESP_BU_ID, t2.CREATE_DATETIME, t2.CLOSED_DATETIME, t2.MESSAGE, t2.MODIFIED_DATETIME, t2.DESCRIPTION, t2.PARENT_WORKITEM_ID, t2.GROUP_IDEN, t2.ORIGINAL_TYPE
FROM PUMA_WORKFLOW_INSTANCE t1, PUMA_WORKITEM t2
WHERE (t1.PRODUCT_ID = :p0) AND (t1.STATEFUL_OBJECT_ID IS NULL) AND (t1.ID = t2.WORKFLOW_ID) AND (NOT (t2.ID IS NULL)) AND (t2.CLOSED_DATETIME IS NULL) - Extra info:
2011-01-18 19:04:24,855 INFO [PumaRobot2-2011-01-18 07:00:25.6579=>()] IssuanceEngine.Data.PumaDataContext Execute: Description: Execute: SELECT t2.ID, t2.WORKFLOW_ID, t2.TASK_ID, t2.TYPE AS "TYPE", t2.PROPRITY, t2.RESP_BU_ID, t2.CREATE_DATETIME, t2.CLOSED_DATETIME, t2.MESSAGE, t2.MODIFIED_DATETIME, t2.DESCRIPTION, t2.PARENT_WORKITEM_ID, t2.GROUP_IDEN, t2.ORIGINAL_TYPE
FROM PUMA_WORKFLOW_INSTANCE t1, PUMA_WORKITEM t2
WHERE (t1.PRODUCT_ID = :p0) AND (t1.STATEFUL_OBJECT_ID IS NULL) AND (t1.ID = t2.WORKFLOW_ID) AND (NOT (t2.ID IS NULL)) AND (t2.CLOSED_DATETIME IS NULL) - Extra info: -1
2011-01-18 19:04:24,871 INFO [PumaRobot2-2011-01-18 07:00:25.6579=>()] IssuanceEngine.Data.PumaDataContext Disconnect: Description: Close connection - Extra info:
2011-01-18 19:04:24,871 INFO [PumaRobot2-2011-01-18 07:00:25.6579=>()] IssuanceEngine.Sotas.ProductSession Found 1 workitems to update for productId=1479917
2011-01-18 19:04:24,871 DEBUG [p526918=>GetWorkItems(WorkItemFilter[MyLineWorkItems, TasksOpenAndInProgress],0)] Puma.Util.DurationCounter GetWorkItems took 46.8753 msecs
2011-01-18 19:04:24,886 INFO [PumaRobot2-2011-01-18 07:00:25.6579=>()] IssuanceEngine.Data.PumaDataContext Prepare: Description: Prepare: SELECT t1.ID, t1.DEFINITION_ID, t1.TASK_STATUS, t1.RESPONSIBLE_BU_MEMBER_ID, t1.LOCKED_DATE_TIME, t1.END_DATE_TIME, t1.STATE_ID, t1.DUE_DATE, t1.ESCALATION_DATE
FROM PUMA_TASK_INSTANCE t1
WHERE :np0 = t1.ID - Extra info:
2011-01-18 19:04:24,886 INFO [PumaRobot2-2011-01-18 07:00:25.6579=>()] IssuanceEngine.Data.PumaDataContext Execute: Description: Execute: SELECT t1.ID, t1.DEFINITION_ID, t1.TASK_STATUS, t1.RESPONSIBLE_BU_MEMBER_ID, t1.LOCKED_DATE_TIME, t1.END_DATE_TIME, t1.STATE_ID, t1.DUE_DATE, t1.ESCALATION_DATE
FROM PUMA_TASK_INSTANCE t1
WHERE :np0 = t1.ID - Extra info: -1

Callstack where it hangs

at OciDynamicType.nativeOCIStmtExecute(HandleRef , HandleRef , HandleRef , Int32 , Int32 , Int32 , Int32 , Int32 )
at OciDynamicType.OCIStmtExecute(HandleRef , HandleRef , HandleRef , Int32 , Int32 , Int32 , Int32 , Int32 )
at Devart.Data.Oracle.ao.a(Int32 A_0, a4 A_1)
at Devart.Data.Oracle.OracleCommand.InternalExecute(CommandBehavior behavior, IDisposable disposable, Int32 startRecord, Int32 maxRecords, Boolean nonQuery)
at Devart.Common.DbCommandBase.ExecuteDbDataReader(CommandBehavior behavior, Boolean nonQuery)
at Devart.Common.DbCommandBase.ExecuteDbDataReader(CommandBehavior behavior)
at System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader()
at Devart.Data.Linq.Provider.DataProvider.a(b A_0, Object[] A_1, Object[] A_2, Object A_3)
at Devart.Data.Linq.Provider.DataProvider.a(b A_0, Object[] A_1)
at Devart.Data.Linq.Provider.DataProvider.b.a(b A_0, Object[] A_1)
at Devart.Data.Linq.Provider.DeferredQuery`3.a(TKeyQuery A_0)
at Devart.Data.Linq.Provider.DefferedEntity`4.a(TKeyQuery A_0)
at Devart.Data.Linq.Provider.DeferredSource`2.b()
at System.Linq.Enumerable.SingleOrDefault[TSource](IEnumerable`1 source)
at System.Data.Linq.EntityRef`1.get_Entity()
at IssuanceEngine.Data.WorkItem.get_Task() in d:\buildbot\slave\release-PuMa-a\build\PumaEngine\IssuanceEngine.Data.Oracle\IssuanceEngineDbContext.WorkItem.cs:line 504
at IssuanceEngine.Sotas.ProductSession.UpdateOpenWorkItems(PumaDataContext context, Product product) in d:\buildbot\slave\release-PuMa-a\build\PumaEngine\IssuanceEngine.Web\ProductSession.cs:line 159
at IssuanceEngine.Web.WorkflowExecution.ExecutionSession.c__DisplayClassed.b__ec() in d:\buildbot\slave\release-PuMa-a\build\PumaEngine\IssuanceEngine.Web\ExecutionSession.cs:line 2915
at IssuanceEngine.Web.WorkflowExecution.ExecutionSession.ExecuteWorkflowStep(PumaDataContext context, String name, Func`1 func) in d:\buildbot\slave\release-PuMa-a\build\PumaEngine\IssuanceEngine.Web\ExecutionSession.cs:line 2941
at IssuanceEngine.Web.WorkflowExecution.ExecutionSession.UpdateOpenWorkitems(PumaDataContext context, Int32 productId) in d:\buildbot\slave\release-PuMa-a\build\PumaEngine\IssuanceEngine.Web\ExecutionSession.cs:line 2911
at IssuanceEngine.BusinessObjects.Workflow.WorkflowObjectProcessThread.ProcessNextItem(IWorkflowExecutionStep next) in d:\buildbot\slave\release-PuMa-a\build\PumaEngine\IssuanceEngine.BusinessObjects\Implementation\Workflow\WorkflowObjectProcessThread.cs:line 99
at IssuanceEngine.BusinessObjects.BaseProcessThread`1.c__DisplayClass6.b__3() in d:\buildbot\slave\release-PuMa-a\build\PumaEngine\IssuanceEngine.BusinessObjects\Implementation\BaseProcessThread.cs:line 254
at IssuanceEngine.BusinessObjects.BaseProcessThread`1.CallProtected(Action method) in d:\buildbot\slave\release-PuMa-a\build\PumaEngine\IssuanceEngine.BusinessObjects\Implementation\BaseProcessThread.cs:line 350
at IssuanceEngine.BusinessObjects.BaseProcessThread`1.ProcessQueue() in d:\buildbot\slave\release-PuMa-a\build\PumaEngine\IssuanceEngine.BusinessObjects\Implementation\BaseProcessThread.cs:line 257
at IssuanceEngine.BusinessObjects.BaseProcessThread`1.MainLoop() in d:\buildbot\slave\release-PuMa-a\build\PumaEngine\IssuanceEngine.BusinessObjects\Implementation\BaseProcessThread.cs:line 205
at Puma.Utilities.Threads.ThreadManager.c__DisplayClasse.b__d() in d:\buildbot\slave\release-PuMa-a\build\PumaEngine\Puma.Utilities\Threads\ThreadManager.cs:line 335
at System.Threading.ThreadHelper.ThreadStart_Context(Object state)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
at System.Threading.ThreadHelper.ThreadStart()

Any guesses? Or should we just abandon Devart and try a different implementation?

bmarotta

It is not the first time I have this error but this time I managed to reproduce it with DbMonitor on.

My application is multithreaded. For some of my contexts I open a connection that is committed on the end. The pattern is always:

Code: Select all

context.Connection.Open();
context.Transaction = Connection.BeginTransaction();
try
{
  // do something
  context.SubmitChanges();
  // do another thing
  context.SubmitChanges();
  context.Transaction.Commit();
}
catch
{
  context.Transaction.Rollback();
}

Sometimes I get the error "Transaction does not match the DataContext.Connection." I could not reproduce the error on my development machine. Only on the server were the application runs under the IIS.

Here follows some lines of the log where the words TRANSACTION or COMMIT appear. The [] is the name of the threads. Please let me know if you want the full logs sent to you.

In the first example, only one thread was starting a transaction. On the second example, two threads at the same time were opening and committing a transaction

2011-01-18 17:33:41,005 INFO [p526918=>CreateProduct(Puma.Transfer.CreateChangeProduct.ProductCreationInitialData)] IssuanceEngine.Data.PumaDataContext Prepare: Description: Prepare: SET TRANSACTION ISOLATION LEVEL READ COMMITTED - Extra info:
2011-01-18 17:33:41,005 INFO [p526918=>CreateProduct(Puma.Transfer.CreateChangeProduct.ProductCreationInitialData)] IssuanceEngine.Data.PumaDataContext Execute: Description: Execute: SET TRANSACTION ISOLATION LEVEL READ COMMITTED - Extra info: -1
2011-01-18 17:33:41,084 INFO [p526918=>CreateProduct(Puma.Transfer.CreateChangeProduct.ProductCreationInitialData)] IssuanceEngine.Data.PumaDataContext Commit: Description: Commit - Extra info:
2011-01-18 17:33:42,318 INFO [p526918=>CreateProduct(Puma.Transfer.CreateChangeProduct.ProductCreationInitialData)] IssuanceEngine.Data.PumaDataContext Prepare: Description: Prepare: SET TRANSACTION ISOLATION LEVEL READ COMMITTED - Extra info:
2011-01-18 17:33:42,318 INFO [p526918=>CreateProduct(Puma.Transfer.CreateChangeProduct.ProductCreationInitialData)] IssuanceEngine.Data.PumaDataContext Execute: Description: Execute: SET TRANSACTION ISOLATION LEVEL READ COMMITTED - Extra info: -1
2011-01-18 17:33:42,599 ERROR [p526918=>CreateProduct(Puma.Transfer.CreateChangeProduct.ProductCreationInitialData)] IssuanceEngine.Data.PumaDataContext Fail to get the DataContext error:Transaction does not match the DataContext.Connection.
2011-01-18 17:33:42,599 INFO [p526918=>CreateProduct(Puma.Transfer.CreateChangeProduct.ProductCreationInitialData)] IssuanceEngine.Data.PumaDataContext Rollback: Description: Rollback - Extra info:

2011-01-18 17:37:43,847 INFO [p526918=>ProcessTaskChanged()] IssuanceEngine.Data.PumaDataContext Prepare: Description: Prepare: SET TRANSACTION ISOLATION LEVEL READ COMMITTED - Extra info:
2011-01-18 17:37:43,863 INFO [p526918=>ProcessTaskChanged()] IssuanceEngine.Data.PumaDataContext Execute: Description: Execute: SET TRANSACTION ISOLATION LEVEL READ COMMITTED - Extra info: -1
2011-01-18 17:37:43,863 INFO [p526918=>ProcessTaskChanged()] IssuanceEngine.Data.PumaDataContext Commit: Description: Commit - Extra info:
2011-01-18 17:38:23,060 INFO [p526918=>AcceptTaskAndSetStatus(5026900,202005)] IssuanceEngine.Data.PumaDataContext Prepare: Description: Prepare: SET TRANSACTION ISOLATION LEVEL READ COMMITTED - Extra info:
pum2011-01-18 17:38:23,060 INFO [p526918=>AcceptTaskAndSetStatus(5026900,202005)] IssuanceEngine.Data.PumaDataContext Execute: Description: Execute: SET TRANSACTION ISOLATION LEVEL READ COMMITTED - Extra info: -1
2011-01-18 17:38:23,107 INFO [p526918=>ProcessTaskChanged()] IssuanceEngine.Data.PumaDataContext Prepare: Description: Prepare: SET TRANSACTION ISOLATION LEVEL READ COMMITTED - Extra info:
2011-01-18 17:38:23,107 INFO [p526918=>ProcessTaskChanged()] IssuanceEngine.Data.PumaDataContext Execute: Description: Execute: SET TRANSACTION ISOLATION LEVEL READ COMMITTED - Extra info: -1
2011-01-18 17:38:23,107 INFO [p526918=>ProcessTaskChanged()] IssuanceEngine.Data.PumaDataContext Commit: Description: Commit - Extra info:
2011-01-18 17:38:23,123 ERROR [p526918=>AcceptTaskAndSetStatus(5026900,202005)] IssuanceEngine.Data.PumaDataContext Fail to get the DataContext error:Transaction does not match the DataContext.Connection.

bmarotta

Hi Stanislav,

although the timeout would workaround the problem, it will not solve it.

As stated before, this problem only happens under heavy usage. As there are other connections problem (like the "Handle is not initialized" exception) which was also "workarounded" by you, my guess is that there must be some run condition in the connections opening and closing that is leaving these calls in an unknown state.

Do you think this is a possible cause? That Devart is closing the connection while the result of an OCI call is still being treated by the OCI dll?

Is there anyway we can monitor the opening and closing of Oracle connections done by Devart or trace all the Oci calls?

Best regards,

bmarotta

I want this build too. I don't want to migrate now and discover thousands of new bugs in thousand different points in the code.

bmarotta

Do you have already a solution for this problem or should we still turn off the compiled query cache? What is the performance impact on it?

bmarotta

Hi Stanislav,

for the Direct mode, I think we have to evaluate it. But it won't be surely done from day to night.

Currently we have the following Oracle versions:

Oracle Server: 10.2.0.4.0 - 64bi

Website Server:
oracle 9 full client Version 9.2.0.1.0
oracle 10 instant client installed. Version 10.2.0.1 (oci.dll)

What is the link between the versions in developer machines and production servers? Is there anything compiled in the code that is linked with the Oracle client version on the compiling machine?

bmarotta

It happens randomly in ANY part of the code under heavy load. By ANY, I mean that any database call can hang. By hang, I mean it stays infinitely there.

It happens mostly on our PROD and PRE-PROD servers which are 8-core machines. On the developer machines (2-core) and other servers (2-core) it is very hard to reproduce.

If you want I can send you an application dump (which is usually a huge file) so that you can analyze it.

I know that the current version we are using does not implement the CommandTimeout correctly. My question is if I will get the CommandTimeout during the fetch also.

bmarotta

I have this error also from time to time on our IIS server on version 5.60.124. This occurs in some background thread and completely crashes the server with no error message.

It looks like dotConnect for Oracle does not work quite well on heavy multithread load.

As you cannot reproduce it, why don't you just catch this error and handle it. Output something and on some log file and don't crash the application.

bmarotta

Hi Stanislaw,

our connection string looks like this:

User Id=xxx;Server=xxx;Persist Security Info=False;Unicode=True

So I guess we are using OCI mode. Is that right?

Do you think we can also solve the problem that it always hangs on the below calls by configuring something on the OCI:

Code: Select all

OciDynamicType.nativeOCIStmtFetch(HandleRef , HandleRef , Int32 , UInt16 , UInt32 )

OciDynamicType.nativeOCIStmtExecute(HandleRef , HandleRef , HandleRef , Int32 , Int32 , Int32 , Int32 , Int32 )

OciDynamicType.nativeOCILobGetLength(HandleRef , HandleRef , IntPtr , Int32& )

OciDynamicType.nativeOCITransCommit(HandleRef , HandleRef , UInt32 )

All of the above calls may randomly hang (by hang I mean they do really never return) and this is really what is killing our application today

Regards,

bmarotta

Hi Stanislaw,

I tried to send you an e-mail, but your mailbox is full. We managed to reproduce the error using your sample. Here is how to do it:

Here is how to reproduce the issue with LoadWith() on the example from Devart:

1) In the Load1()
change:

Code: Select all

dc.Emps.LoadWith(e => e.Dept);        
Console.WriteLine("First context: related Dept is {0} null", dc.Emps.FirstOrDefault().Dept == null ? "" : "not");

With:

Code: Select all

Console.WriteLine("First context: related Dept is {0} null", dc.Emps.LoadWith(e => e.Dept).FirstOrDefault().Dept == null ? "" : "not");
//call of the 2nd thread here!
Thread th2 = new Thread(Load2);
th2.Start();

2) In the Main()

remove or comment :

Code: Select all

      // Thread th2 = new Thread(Load2);
      // th2.Start();

Please let me know if you manage to reproduce it (or when your mailbox is back again)

Best regards,

bmarotta

Hi Stanislaw,

sorry but we didn't have time yet to try to reproduce the LoadWith on your test application. But anyway, was the connection timeout problem solved on the last Release? We really need this thing fixed...

bmarotta

Hi Stanislav,

thanks for the tips. I've already tried the connection timeout and it does not work. At least I never got one and I still have the random hangings on my server.

I tried turning off the pooling but, for my surprise, when doing so, the connection gets randomly closed by the context!!!

If I do:

Code: Select all

context.connection.Open()

context.Transaction = Connection.BeginTransaction();

context.SubmitChanges();

... Do my stuff here. So other queries, I don't no

context.Transaction.Commit();

I get an error on the Commit: Connection must be opened.

If I check the context.Connection.State, it is closed. I am pretty sure this is a bug. At least on the 5.60.124 version.

Any other ideas?!

bmarotta

Hi Stanislav,

it is hard to send a small example, because our project is huge.

What I can tell is that previously the workitem.Task was not null even without the LoadWith. If you say this is suppose to be like this than it is a new feature, meaning that we will have to go throughout our whole code and add LoadWith for all entities that previously were loaded on demand.

What I can tell you also is that in many parts of the code, we have a similar relationship, and the entity is not set to null. It is only set to null if, somewhere in the code you do a LoadWith and than in another part of the code, with a completely different context, you don't do it.

Search found 34 matches

ORA-01483: invalid length for DATE or NUMBER

Transaction does not match the DataContext.Connection