Pages: 1

#1 2017-05-03 21:13:02

ASiwon
Member
From: Poland
Registered: 2015-01-30
Posts: 82

Unexpected Access Violation exception on service call

Hi,

i found in log of my application an unexpected Access Violation exception. Here is fragment of log file:

10:42:43	Enter	16	                         mORMotSQLite3.TSQLRestServerDB(0126E7D0).URI(POST root/BkKomunikatyOperator.LogujWyswietlenie/6648 inlen=13)
10:42:43	Service call	16	                            mORMotSQLite3.TSQLRestServerDB(0126E7D0) BkKomunikatyOperator.LogujWyswietlenie[98754,10561]
10:42:43	Debug	16	                            mORMotSQLite3.TSQLRestServerDB(0126E7D0) TServiceFactoryServer.InternalInstanceRetrieve: Deleted BkKomunikatyOperator instance (id=6684) after 1917563 ms timeout (max 1800000 ms)
10:42:43	Info	16	                            mORMotSQLite3.TSQLRestClientDB(01D0D340) TSQLRestClientDB.Destroy -> {"TSQLRestClientDB(01D0D340)":{"LastErrorCode":200,"LastErrorMessage":"","MaximumAuthentificationRetry":0,"RetryOnceOnTimeout":false,"SessionID":1,"SessionServer":"","SessionVersion":"","ServerTimeStamp":135374875306}}
10:42:43	Debug	16	                            mORMotSQLite3.TSQLRestServerDB(0126E7D0) TServiceFactoryServer.InternalInstanceRetrieve: Deleted BkKomunikatyOperator instance (id=6996) after 1917547 ms timeout (max 1800000 ms)
10:42:43	Info	16	                            mORMotSQLite3.TSQLRestClientDB(01D0C140) TSQLRestClientDB.Destroy -> {"TSQLRestClientDB(01D0C140)":{"LastErrorCode":200,"LastErrorMessage":"","MaximumAuthentificationRetry":0,"RetryOnceOnTimeout":false,"SessionID":1,"SessionServer":"","SessionVersion":"","ServerTimeStamp":135374875306}}
10:42:43	Debug	16	                            mORMotSQLite3.TSQLRestServerDB(0126E7D0) TServiceFactoryServer.InternalInstanceRetrieve: Deleted BkKomunikatyOperator instance (id=6264) after 3078891 ms timeout (max 1800000 ms)
10:42:43	Info	16	                            mORMotSQLite3.TSQLRestClientDB(01D0CFE0) TSQLRestClientDB.Destroy -> {"TSQLRestClientDB(01D0CFE0)":{"LastErrorCode":200,"LastErrorMessage":"","MaximumAuthentificationRetry":0,"RetryOnceOnTimeout":false,"SessionID":1,"SessionServer":"","SessionVersion":"","ServerTimeStamp":135374875306}}
10:42:43	Debug	16	                            mORMotSQLite3.TSQLRestServerDB(0126E7D0) TServiceFactoryServer.InternalInstanceRetrieve: Deleted BkKomunikatyOperator instance (id=6796) after 1984094 ms timeout (max 1800000 ms)
10:42:43	Info	16	                            mORMotSQLite3.TSQLRestClientDB(01D0D580) TSQLRestClientDB.Destroy -> {"TSQLRestClientDB(01D0D580)":{"LastErrorCode":200,"LastErrorMessage":"","MaximumAuthentificationRetry":0,"RetryOnceOnTimeout":false,"SessionID":1,"SessionServer":"","SessionVersion":"","ServerTimeStamp":135374875306}}
10:42:43	Debug	16	                            mORMotSQLite3.TSQLRestServerDB(0126E7D0) TServiceFactoryServer.InternalInstanceRetrieve: Deleted BkKomunikatyOperator instance (id=1492) after 3008329 ms timeout (max 1800000 ms)
10:42:43	Info	16	                            mORMotSQLite3.TSQLRestClientDB(01D0CEC0) TSQLRestClientDB.Destroy -> {"TSQLRestClientDB(01D0CEC0)":{"LastErrorCode":201,"LastErrorMessage":"","MaximumAuthentificationRetry":0,"RetryOnceOnTimeout":false,"SessionID":1,"SessionServer":"","SessionVersion":"","ServerTimeStamp":135374875306}}
10:42:43	Debug	16	                            mORMotSQLite3.TSQLRestServerDB(0126E7D0) TServiceFactoryServer.InternalInstanceRetrieve: Deleted BkKomunikatyOperator instance (id=6800) after 3008313 ms timeout (max 1800000 ms)
10:42:43	Info	16	                            mORMotSQLite3.TSQLRestClientDB(01D0D8E0) TSQLRestClientDB.Destroy -> {"TSQLRestClientDB(01D0D8E0)":{"LastErrorCode":200,"LastErrorMessage":"","MaximumAuthentificationRetry":0,"RetryOnceOnTimeout":false,"SessionID":1,"SessionServer":"","SessionVersion":"","ServerTimeStamp":135374875306}}
10:42:43	Debug	16	                            mORMotSQLite3.TSQLRestServerDB(0126E7D0) TServiceFactoryServer.InternalInstanceRetrieve: Deleted BkKomunikatyOperator instance (id=6464) after 1983813 ms timeout (max 1800000 ms)
10:42:43	Info	16	                            mORMotSQLite3.TSQLRestClientDB(01D0CC80) TSQLRestClientDB.Destroy -> {"TSQLRestClientDB(01D0CC80)":{"LastErrorCode":200,"LastErrorMessage":"","MaximumAuthentificationRetry":0,"RetryOnceOnTimeout":false,"SessionID":1,"SessionServer":"","SessionVersion":"","ServerTimeStamp":135374875307}}
10:42:43	Debug	16	                            mORMotSQLite3.TSQLRestServerDB(0126E7D0) TServiceFactoryServer.InternalInstanceRetrieve: Deleted BkKomunikatyOperator instance (id=6224) after 2519141 ms timeout (max 1800000 ms)
10:42:43	Info	16	                            mORMotSQLite3.TSQLRestClientDB(01D0C020) TSQLRestClientDB.Destroy -> {"TSQLRestClientDB(01D0C020)":{"LastErrorCode":200,"LastErrorMessage":"","MaximumAuthentificationRetry":0,"RetryOnceOnTimeout":false,"SessionID":1,"SessionServer":"","SessionVersion":"","ServerTimeStamp":135374875306}}
10:42:43	Debug	16	                            mORMotSQLite3.TSQLRestServerDB(0126E7D0) TServiceFactoryServer.InternalInstanceRetrieve: Deleted BkKomunikatyOperator instance (id=6648) after 1877672 ms timeout (max 1800000 ms)
10:42:43	Info	16	                            mORMotSQLite3.TSQLRestClientDB(01D0CB60) TSQLRestClientDB.Destroy -> {"TSQLRestClientDB(01D0CB60)":{"LastErrorCode":200,"LastErrorMessage":"","MaximumAuthentificationRetry":0,"RetryOnceOnTimeout":false,"SessionID":1,"SessionServer":"","SessionVersion":"","ServerTimeStamp":135374875306}}
10:42:43	Debug	16	                            mORMotSQLite3.TSQLRestServerDB(0126E7D0) TServiceFactoryServer.InternalInstanceRetrieve: Deleted BkKomunikatyOperator instance (id=6976) after 1982860 ms timeout (max 1800000 ms)
10:42:43	Info	16	                            mORMotSQLite3.TSQLRestClientDB(01D0D460) TSQLRestClientDB.Destroy -> {"TSQLRestClientDB(01D0D460)":{"LastErrorCode":200,"LastErrorMessage":"","MaximumAuthentificationRetry":0,"RetryOnceOnTimeout":false,"SessionID":1,"SessionServer":"","SessionVersion":"","ServerTimeStamp":135374875306}}
10:42:43	Debug	16	                            mORMotSQLite3.TSQLRestServerDB(0126E7D0) TServiceFactoryServer.InternalInstanceRetrieve: Deleted BkKomunikatyOperator instance (id=5044) after 1917579 ms timeout (max 1800000 ms)
10:42:43	Info	16	                            mORMotSQLite3.TSQLRestClientDB(01D0C380) TSQLRestClientDB.Destroy -> {"TSQLRestClientDB(01D0C380)":{"LastErrorCode":201,"LastErrorMessage":"","MaximumAuthentificationRetry":0,"RetryOnceOnTimeout":false,"SessionID":1,"SessionServer":"","SessionVersion":"","ServerTimeStamp":135374875306}}
10:42:43	Debug	16	                            mORMotSQLite3.TSQLRestServerDB(0126E7D0) TServiceFactoryServer.InternalInstanceRetrieve: Deleted BkKomunikatyOperator instance (id=6228) after 3359766 ms timeout (max 1800000 ms)
10:42:43	Info	16	                            mORMotSQLite3.TSQLRestClientDB(01D0D7C0) TSQLRestClientDB.Destroy -> {"TSQLRestClientDB(01D0D7C0)":{"LastErrorCode":200,"LastErrorMessage":"","MaximumAuthentificationRetry":0,"RetryOnceOnTimeout":false,"SessionID":1,"SessionServer":"","SessionVersion":"","ServerTimeStamp":135374875306}}
10:42:43	Debug	16	                            mORMotSQLite3.TSQLRestServerDB(0126E7D0) TServiceFactoryServer.InternalInstanceRetrieve: Deleted BkKomunikatyOperator instance (id=6812) after 3359766 ms timeout (max 1800000 ms)
10:42:43	Info	16	                            mORMotSQLite3.TSQLRestClientDB(01D0C260) TSQLRestClientDB.Destroy -> {"TSQLRestClientDB(01D0C260)":{"LastErrorCode":200,"LastErrorMessage":"","MaximumAuthentificationRetry":0,"RetryOnceOnTimeout":false,"SessionID":1,"SessionServer":"","SessionVersion":"","ServerTimeStamp":135374875306}}
10:42:43	Debug	16	                            mORMotSQLite3.TSQLRestServerDB(0126E7D0) TServiceFactoryServer.InternalInstanceRetrieve: Deleted BkKomunikatyOperator instance (id=6236) after 1982579 ms timeout (max 1800000 ms)
10:42:43	Info	16	                            mORMotSQLite3.TSQLRestClientDB(01D0C6E0) TSQLRestClientDB.Destroy -> {"TSQLRestClientDB(01D0C6E0)":{"LastErrorCode":200,"LastErrorMessage":"","MaximumAuthentificationRetry":0,"RetryOnceOnTimeout":false,"SessionID":1,"SessionServer":"","SessionVersion":"","ServerTimeStamp":135374875307}}
10:42:43	Debug	16	                            mORMotSQLite3.TSQLRestServerDB(0126E7D0) TServiceFactoryServer.InternalInstanceRetrieve: Deleted BkKomunikatyOperator instance (id=6232) after 1917579 ms timeout (max 1800000 ms)
10:42:43	Info	16	                            mORMotSQLite3.TSQLRestClientDB(01D0CDA0) TSQLRestClientDB.Destroy -> {"TSQLRestClientDB(01D0CDA0)":{"LastErrorCode":201,"LastErrorMessage":"","MaximumAuthentificationRetry":0,"RetryOnceOnTimeout":false,"SessionID":1,"SessionServer":"","SessionVersion":"","ServerTimeStamp":135374875306}}
10:42:43	Enter	17	                   mORMotSQLite3.TSQLRestServerDB(0126E7D0).URI(POST root/BkKomunikatyOperator.LogujWyswietlenie/6996 inlen=13)
10:42:43	Service call	17	                      mORMotSQLite3.TSQLRestServerDB(0126E7D0) BkKomunikatyOperator.LogujWyswietlenie[98754,10533]

<Here is a problem>

10:42:43	Debug	16	                            mORMotSQLite3.TSQLRestServerDB(0126E7D0) TServiceFactoryServer.InternalInstanceRetrieve: Deleted BkKomunikatyOperator instance (id=6804) after 1983110 ms timeout (max 1800000 ms)
10:42:43	Debug	17	                      mORMotSQLite3.TSQLRestServerDB(0126E7D0) TServiceFactoryServer.InternalInstanceRetrieve: Deleted BkKomunikatyOperator instance (id=6804) after 1983110 ms timeout (max 1800000 ms)
10:42:43	Info	16	                            mORMotSQLite3.TSQLRestClientDB(01D0C4A0) TSQLRestClientDB.Destroy -> {"TSQLRestClientDB(01D0C4A0)":{"LastErrorCode":200,"LastErrorMessage":"","MaximumAuthentificationRetry":0,"RetryOnceOnTimeout":false,"SessionID":1,"SessionServer":"","SessionVersion":"","ServerTimeStamp":135374875306}}
10:42:43	Debug	16	                            mORMotSQLite3.TSQLRestServerDB(0126E7D0) TServiceFactoryServer.InternalInstanceRetrieve: Deleted BkKomunikatyOperator instance (id=6992) after 1983344 ms timeout (max 1800000 ms)
10:42:43	Info	16	                            mORMotSQLite3.TSQLRestClientDB(01D0D100) TSQLRestClientDB.Destroy -> {"TSQLRestClientDB(01D0D100)":{"LastErrorCode":200,"LastErrorMessage":"","MaximumAuthentificationRetry":0,"RetryOnceOnTimeout":false,"SessionID":1,"SessionServer":"","SessionVersion":"","ServerTimeStamp":135374875306}}
10:42:43	Debug	16	                            mORMotSQLite3.TSQLRestServerDB(0126E7D0) TServiceFactoryServer.InternalInstanceRetrieve: Adding BkKomunikatyOperator instance (id=1492)
10:42:43	Enter	16	                            uBkKomunikatyOperatorzy.TBkSerwisKomunikatyOperator(045D8740).LogujWyswietlenie
10:42:43	Debug	16	                               Wykonano preparację struktury.
10:42:43	Enter	16	                               mORMotSQLite3.TSQLRestClientDB(01D0D100).CallBackGet root/TimeStamp
10:42:43	Enter	16	                                  mORMotSQLite3.TSQLRestServerDB(0126E7D0).URI(GET root/TimeStamp inlen=0)
10:42:43	Service call	16	                                     mORMotSQLite3.TSQLRestServerDB(0126E7D0) TimeStamp 
10:42:43	Server	16	                                     mORMotSQLite3.TSQLRestServerDB(0126E7D0)   GET root/TimeStamp SOA-Method -> 200 with outlen=12 in 16 us
10:42:43	Service return	16	                                     mORMotSQLite3.TSQLRestServerDB(0126E7D0) 135374875307
10:42:43	Leave	16	                                  00.000.027
10:42:43	Service return	16	                                  mORMotSQLite3.TSQLRestClientDB(01D0D100) 135374875307
10:42:43	Leave	16	                               00.000.036
10:42:43	Enter	16	                               mORMotSQLite3.TSQLRestServerDB(0126E7D0).URI(POST root/BkKomunikatLog inlen=126)
10:42:43	Exception OS	17	                      EAccessViolation (C0000005) at 006FC205  stack trace 5006119C 007993F8 007B1142 011D0BC8 0079D39F 007A1DED 5016C3B9 50060BA6 751F7C04 770CAB8F 770CAB5A 
10:42:43	Debug	16	                                  Statement cache HIT
10:42:43	SQL	16	                                  SynDBOracle.TSQLDBOracleStatement(01D0C4A0) insert into U_BTK.T_BTK_KOMUNIKATY_LOGI (kml_id,kml_czas_sprawdzenia,kml_czas_wyswietl,kml_czas_zamkniecia,kml_km_id,kml_uz_id) values (315479,NULL,'2017-04-29 12:42:43',NULL,98754,10561)
10:42:43	Debug	17	                      mORMotSQLite3.TSQLRestServerDB(0126E7D0) TSQLRestRoutingREST.Error: {  "errorCode":500,  "error":  {"EAccessViolation":{"EAccessViolation":"Access violation at address 006FC205 in module 'MORMotCore18.bpl'. Read of address 00000000"}}  }
10:42:43	Server	17	                      mORMotSQLite3.TSQLRestServerDB(0126E7D0)   POST root/BkKomunikatyOperator.LogujWyswietlenie SOA-Interface -> 500 with outlen=169 in 1325 us
10:42:43	Leave	17	                   00.001.338
10:42:43	DB	16	                                  SynDBOracle.TSQLDBOracleStatement(01D0C4A0) 0 row(s) in 2.25ms
10:42:43	Server	16	                                  mORMotSQLite3.TSQLRestServerDB(0126E7D0)   POST root/BkKomunikatLog ORM-Write -> 201 with outlen=0 in 2339 us
10:42:43	Leave	16	                               00.002.352
10:42:43	Debug	16	                               Dodano zapis o wyświetleniu komunikatu. Id: 315479
10:42:43	Leave	16	                            00.002.435
10:42:43	Server	16	                            mORMotSQLite3.TSQLRestServerDB(0126E7D0)   POST root/BkKomunikatyOperator.LogujWyswietlenie SOA-Interface -> 200 with outlen=29 in 4004 us
10:42:43	Service return	16	                            mORMotSQLite3.TSQLRestServerDB(0126E7D0) {"result":[315479],"id":1492}
10:42:43	Leave	16	                         00.004.018

As you can see at some point thread 16 deletes BkKomunikatyOperator instance (id=6804) in the next step thread 17 deletes the same BkKomunikatyOperator instance. Instance is destroyed in thread 16 and in thread 17 Access Violation exception is thrown. I'm very suprised with this results. I have check source code and I see that InternalInstanceRetrieve is protected using critical section so two thread shouldn't execute this method in the same time. Could anybody help me to explain or resolve this problem? Any help will be very appreciated.

I'm using mORMot revision (3815 from SVN repository, 2017 February 28, 11:42:24) and Delphi XE4 Pro. Service is registered as sicPerThread.

best regards
Adam Siwon

Offline

#2 2017-05-03 21:38:14

ab
Administrator
From: France
Registered: 2010-06-21
Posts: 14,655
Website

Re: Unexpected Access Violation exception on service call

Fixed since months AFAIR.
There was a random Access Violation at TSqlRest destroying.

Offline

#3 2017-05-04 06:09:59

ASiwon
Member
From: Poland
Registered: 2015-01-30
Posts: 82

Re: Unexpected Access Violation exception on service call

Hi,

indeed. The problem occurs in older version of my application, which was linked to the older version of mORMot. I think now everything will works correctly. Thank you very much for answer.

best regards
Adam Siwon

Offline

Pages: 1

Board footer

Powered by FluxBB