Date field Index is corrupted due to time change

#1

Hi,

can you shed some light on why we cannot delete data from the attached DB file. A delete attempt with DB explorer results in the following exception:

[ObjectDB 2.6.3] Unexpected exception (Error 990)
  Generated by Java HotSpot(TM) 64-Bit Server VM 1.7.0_80 (on Linux 2.6.32-279.9.1.el6.x86_64).
Please report this error on http://www.objectdb.com/database/issue/new
com.objectdb.o.InternalException: null
com.objectdb.o.InternalException
        at com.objectdb.o.InternalException.f(InternalException.java:236)
        at com.objectdb.o.SPW.an(SPW.java:109)
        at com.objectdb.o.PGW.aj(PGW.java:220)
        at com.objectdb.o.UPT.C(UPT.java:134)
        at com.objectdb.o.UPT.l(UPT.java:110)
        at com.objectdb.o.TSK.i(TSK.java:145)
        at com.objectdb.o.TSK.f(TSK.java:95)
        at com.objectdb.o.UPT.s(UPT.java:157)
        at com.objectdb.o.PGT.q(PGT.java:109)
        at com.objectdb.o.UPT.C(UPT.java:121)
        at com.objectdb.o.UPT.l(UPT.java:110)
        at com.objectdb.o.TSK.i(TSK.java:145)
        at com.objectdb.o.TSK.f(TSK.java:95)
        at com.objectdb.o.UPT.s(UPT.java:157)
        at com.objectdb.o.PGT.q(PGT.java:109)
        at com.objectdb.o.UPT.C(UPT.java:121)
        at com.objectdb.o.URT.l(URT.java:171)
        at com.objectdb.o.TSK.i(TSK.java:145)
        at com.objectdb.o.TSK.f(TSK.java:95)
        at com.objectdb.o.TSM.e(TSM.java:86)
        at com.objectdb.o.UTT.A(UTT.java:370)
        at com.objectdb.o.UTT.l(UTT.java:223)
        at com.objectdb.o.TSK.i(TSK.java:145)
        at com.objectdb.o.TSK.f(TSK.java:95)
        at com.objectdb.o.MST.Vg(MST.java:1337)
        at com.objectdb.o.PRG.ak(PRG.java:952)
        at com.objectdb.o.PRG.ag(PRG.java:659)
        at com.objectdb.o.PRG.af(PRG.java:553)
        at com.objectdb.o.QRM.Vb(QRM.java:286)
        at com.objectdb.o.MST.Vb(MST.java:988)
        at com.objectdb.o.WRA.Vb(WRA.java:311)
        at com.objectdb.o.WSM.Vb(WSM.java:115)
        at com.objectdb.o.QRR.g(QRR.java:247)
        at com.objectdb.o.QRR.f(QRR.java:153)
        at com.objectdb.jpa.JpaQuery.executeUpdate(JpaQuery.java:776)
        at com.objectdb.o.QRP.L(QRP.java:251)
        at com.objectdb.o.QRP.T(QRP.java:723)
        at com.objectdb.o.QRP.actionPerformed(QRP.java:686)
        at javax.swing.AbstractButton.fireActionPerformed(AbstractButton.java:2018)
        at javax.swing.AbstractButton$Handler.actionPerformed(AbstractButton.java:2341)

The problem started happening without any obvious reason.

I should mention that running DB Doctor on it shows the following issues:

root@localhost totalrecall]# ./dbDoctor.sh db/SystemDB.odb db/SystemDB.odb.rpmnew
ObjectDB Doctor [version 2.6.3]
Copyright (c) 2015, ObjectDB Software. All rights reserved.

Scanning the database file...
.................................................. 100MB
.................................................. 200MB
.................................................. 300MB
.................................................. 400MB
.................................................. 500MB
.................................................. 600MB
.................................................. 700MB
.................................................. 800MB
.................................................. 900MB
.................................................. 1000MB
........... 1024MB (total)

Analyzing database structure...
10% 20% 30% 40% 50% 60% 70% 80% 90% 100%

Page Relation Errors
--------------------
[1] Page #12592 last key is 2015-10-24 03:00:00|1:71540, parent page #10513 next key is 2015-10-24 03:00:00
[2] Page #12804 last key is 2015-10-24 03:00:00|1:72811, parent page #10513 next key is 2015-10-24 03:00:00|1:71594

Page Content Errors
-------------------
[1] Page #12750 has unsorted entries
[2] Page #12750 has unsorted entries
[3] Page #12750 has unsorted entries
[4] Page #12750 has unsorted entries
[5] Page #12750 has unsorted entries
[6] Page #12750 has unsorted entries
[7] Page #12750 has unsorted entries
[8] Page #12750 has unsorted entries
[9] Page #12750 has unsorted entries

[10] Page #12750 has unsorted entries
[11] Page #12750 has unsorted entries
[12] Page #12750 has unsorted entries
[13] Page #12750 has unsorted entries
[14] Page #12750 has unsorted entries
[15] Page #12750 has unsorted entries
[16] Page #12750 has unsorted entries
[17] Page #12750 has unsorted entries
[18] Page #12750 has unsorted entries
[19] Page #12750 has unsorted entries
[20] Page #12750 has unsorted entries
[21] Page #12750 has unsorted entries
[22] Page #12750 has unsorted entries
[23] Page #12750 has unsorted entries
[24] Page #12750 has unsorted entries
[25] Page #12750 has unsorted entries
[26] Page #12750 has unsorted entries
[27] Page #12750 has unsorted entries
[28] Page #12750 has unsorted entries
[29] Page #12750 has unsorted entries
[30] Page #12750 has unsorted entries
[31] Page #12750 has unsorted entries
[32] Page #12750 has unsorted entries
[33] Page #12750 has unsorted entries
[34] Page #12750 has unsorted entries
[35] Page #12750 has unsorted entries
[36] Page #12750 has unsorted entries
[37] Page #12750 has unsorted entries
[38] Page #12750 has unsorted entries
[39] Page #12750 has unsorted entries
[40] Page #12750 has unsorted entries
[41] Page #12750 has unsorted entries
[42] Page #12750 has unsorted entries
[43] Page #12750 has unsorted entries
[44] Page #12750 has unsorted entries
[45] Page #12750 has unsorted entries
[46] Page #12750 has unsorted entries
[47] Page #12776 has unsorted entries
[48] Page #12776 has unsorted entries
[49] Page #12776 has unsorted entries
[50] Page #12776 has unsorted entries
[51] Page #12776 has unsorted entries
[52] Page #12776 has unsorted entries
[53] Page #12776 has unsorted entries
[54] Page #12776 has unsorted entries
[55] Page #12776 has unsorted entries
[56] Page #12776 has unsorted entries
[57] Page #12776 has unsorted entries
[58] Page #12776 has unsorted entries
[59] Page #12776 has unsorted entries
[60] Page #12776 has unsorted entries
[61] Page #12776 has unsorted entries
[62] Page #12776 has unsorted entries
[63] Page #12776 has unsorted entries
[64] Page #12776 has unsorted entries
[65] Page #12776 has unsorted entries
[66] Page #12776 has unsorted entries
[67] Page #12776 has unsorted entries
[68] Page #12776 has unsorted entries
[69] Page #12776 has unsorted entries
[70] Page #12776 has unsorted entries
[71] Page #12776 has unsorted entries
[72] Page #12776 has unsorted entries
[73] Page #12776 has unsorted entries
[74] Page #12776 has unsorted entries
[75] Page #12776 has unsorted entries
[76] Page #12776 has unsorted entries
[77] Page #12776 has unsorted entries
[78] Page #12793 has unsorted entries
[79] Page #12793 has unsorted entries
[80] Page #12793 has unsorted entries
[81] Page #12793 has unsorted entries
[82] Page #12793 has unsorted entries
[83] Page #12793 has unsorted entries
[84] Page #12793 has unsorted entries
[85] Page #12793 has unsorted entries
[86] Page #12793 has unsorted entries
[87] Page #12793 has unsorted entries
[88] Page #12793 has unsorted entries
[89] Page #12793 has unsorted entries
[90] Page #12793 has unsorted entries
[91] Page #12793 has unsorted entries
[92] Page #12793 has unsorted entries
[93] Page #12793 has unsorted entries
[94] Page #12793 has unsorted entries
[95] Page #12793 has unsorted entries
[96] Page #12793 has unsorted entries
[97] Page #12793 has unsorted entries
[98] Page #12793 has unsorted entries
[99] Page #12793 has unsorted entries
[100] Page #12793 has unsorted entries
[101] Page #12793 has unsorted entries
[102] Page #12793 has unsorted entries
[103] Page #12793 has unsorted entries
[104] Page #12793 has unsorted entries
[105] Page #12793 has unsorted entries
[106] Page #12793 has unsorted entries
[107] Page #12793 has unsorted entries
[108] Page #12793 has unsorted entries
[109] Page #12793 has unsorted entries
[110] Page #12793 has unsorted entries
[111] Page #12793 has unsorted entries
[112] Page #12793 has unsorted entries
[113] Page #12793 has unsorted entries
[114] Page #12793 has unsorted entries
[115] Page #12793 has unsorted entries
[116] Page #12793 has unsorted entries
[117] Page #12793 has unsorted entries
[118] Page #12793 has unsorted entries
[119] Page #12793 has unsorted entries
[120] Page #12793 has unsorted entries
[121] Page #12793 has unsorted entries
[122] Page #12793 has unsorted entries
[123] Page #12793 has unsorted entries
[124] Page #12793 has unsorted entries
[125] Page #12793 has unsorted entries
[126] Page #12794 has unsorted entries
[127] Page #12794 has unsorted entries
[128] Page #12794 has unsorted entries
[129] Page #12794 has unsorted entries
[130] Page #12794 has unsorted entries
[131] Page #12794 has unsorted entries
[132] Page #12794 has unsorted entries
[133] Page #12794 has unsorted entries
[134] Page #12794 has unsorted entries
[135] Page #12794 has unsorted entries
[136] Page #12794 has unsorted entries
[137] Page #12794 has unsorted entries
[138] Page #12794 has unsorted entries
[139] Page #12794 has unsorted entries
[140] Page #12794 has unsorted entries
[141] Page #12794 has unsorted entries
[142] Page #12794 has unsorted entries
[143] Page #12794 has unsorted entries
[144] Page #12794 has unsorted entries
[145] Page #12794 has unsorted entries
[146] Page #12794 has unsorted entries
[147] Page #12794 has unsorted entries
[148] Page #12794 has unsorted entries
[149] Page #12794 has unsorted entries
[150] Page #12794 has unsorted entries
[151] Page #12794 has unsorted entries
[152] Page #12794 has unsorted entries
[153] Page #12794 has unsorted entries
[154] Page #12794 has unsorted entries
[155] Page #12794 has unsorted entries
[156] Page #12794 has unsorted entries
[157] Page #12794 has unsorted entries
[158] Page #12794 has unsorted entries
[159] Page #12794 has unsorted entries
[160] Page #12794 has unsorted entries
[161] Page #12794 has unsorted entries
[162] Page #12794 has unsorted entries
[163] Page #12794 has unsorted entries
[164] Page #12794 has unsorted entries
[165] Page #12794 has unsorted entries
[166] Page #12794 has unsorted entries
[167] Page #12794 has unsorted entries
[168] Page #12794 has unsorted entries
[169] Page #12794 has unsorted entries
[170] Page #12794 has unsorted entries
[171] Page #12794 has unsorted entries
[172] Page #12794 has unsorted entries
[173] Page #12794 has unsorted entries
[174] Page #12795 has unsorted entries
[175] Page #12795 has unsorted entries
[176] Page #12795 has unsorted entries
[177] Page #12795 has unsorted entries
[178] Page #12795 has unsorted entries
[179] Page #12795 has unsorted entries
[180] Page #12795 has unsorted entries
[181] Page #12795 has unsorted entries
[182] Page #12795 has unsorted entries
[183] Page #12795 has unsorted entries
[184] Page #12795 has unsorted entries
[185] Page #12795 has unsorted entries
[186] Page #12795 has unsorted entries
[187] Page #12795 has unsorted entries
[188] Page #12795 has unsorted entries
[189] Page #12795 has unsorted entries
[190] Page #12795 has unsorted entries
[191] Page #12795 has unsorted entries
[192] Page #12795 has unsorted entries
[193] Page #12795 has unsorted entries
[194] Page #12795 has unsorted entries
[195] Page #12795 has unsorted entries
[196] Page #12795 has unsorted entries
[197] Page #12795 has unsorted entries
[198] Page #12795 has unsorted entries
[199] Page #12795 has unsorted entries
[200] Page #12795 has unsorted entries
[201] Page #12795 has unsorted entries
[202] Page #12795 has unsorted entries
[203] Page #12795 has unsorted entries
[204] Page #12795 has unsorted entries
[205] Page #12795 has unsorted entries
[206] Page #12795 has unsorted entries
[207] Page #12795 has unsorted entries
[208] Page #12795 has unsorted entries
[209] Page #12795 has unsorted entries
[210] Page #12795 has unsorted entries
[211] Page #12795 has unsorted entries
[212] Page #12795 has unsorted entries
[213] Page #12795 has unsorted entries
[214] Page #12795 has unsorted entries
[215] Page #12795 has unsorted entries
[216] Page #12795 has unsorted entries
[217] Page #12795 has unsorted entries
[218] Page #12795 has unsorted entries
[219] Page #12795 has unsorted entries
[220] Page #12795 has unsorted entries
[221] Page #12795 has unsorted entries
[222] Page #12802 has unsorted entries
[223] Page #12802 has unsorted entries
[224] Page #12802 has unsorted entries
[225] Page #12802 has unsorted entries
[226] Page #12803 has unsorted entries
[227] Page #12803 has unsorted entries
[228] Page #12803 has unsorted entries
[229] Page #12803 has unsorted entries
[230] Page #12804 has unsorted entries
[231] Page #12804 has unsorted entries
[232] Page #12804 has unsorted entries
[233] Page #12804 has unsorted entries
[234] Page #12804 has unsorted entries
[235] Page #12804 has unsorted entries
[236] Page #12804 has unsorted entries
[237] Page #12804 has unsorted entries
[238] Page #12804 has unsorted entries
[239] Page #12804 has unsorted entries
[240] Page #12804 has unsorted entries
[241] Page #12804 has unsorted entries
[242] Page #12804 has unsorted entries
[243] Page #12804 has unsorted entries
[244] Page #12804 has unsorted entries
[245] Page #12806 has unsorted entries
[246] Page #12806 has unsorted entries
[247] Page #12806 has unsorted entries
[248] Page #12806 has unsorted entries

Creating a database copy...
  820 entity objects (total) have been migrated.

New database copy is ready at: db/SystemDB.odb.rpmnew

 

 

Thank you

Emil 

 

#2

As reported by the Doctor, unfortunately this database file is corrupted, so the error message that you got on an attempt to delete objects could happen with other operations as well.

The common reason for database corruption is usually an external activity, such as copying a database file while it is active (the new copy may be corrupted) or copying a database file after abnormal close without its associated recovery file. However, it is also possible (although extremely rare) that the specific activity in your application is not supported well by ObjectDB and some hidden unknown bug may be the cause.

Could you please provide more information about this specific database file that may be relevant in understanding the cause? Can you reproduce this, i.e. generate a new corrupted database using your application or a test case?

ObjectDB Support
#3

Hi,

we are trying to replicate the problem and I will post results if we are successful.

As for the use of the DB, our use is very basic, simple (I guess):

  1. We create a 1G DB file when the application starts for the fist time. The size of the DB file does not change during the life of the system as it is large enough to contain all objects we ever want to store in it.
  2. We use the DB in embedded mode.
  3. There is only one object type that we store in the DB, as you can see from the DB file.
  4. All DB operations are sequential, i.e. only one DB operation runs at any one time.
  5. The load never exceeds more than 5 transactions per 10 seconds.

 

So far we know this about the environment that caused the problem:

  1. The problem happened the morning on Sunday 25th of October at 3am. We think this is significant as this is exactly the time when Madrid changed clocks one hour back and moved from CEST to CET time.
  2. We store time data as part of the object, but we do not think this is relevant.
  3. Atthe time of the problem the load was at most 1 transction per 10 seconds.
  4. All other functions of the system continued as usual, however the DB started reporting the following exception every time an attempt was made to add a record to the DB.

 

2015-10-28 13:51:35,552 ERROR [Sniffer Provider Timer] - Failed to add Recording (meta data) to the DB
[ObjectDB 2.5.5_14] javax.persistence.RollbackException
Failed to commit transaction:  (error 613)
at com.objectdb.jpa.EMImpl.commit(EMImpl.java:302)
at com.arunta.base.db.RecordingMetaDataDAO.commitTxn(RecordingMetaDataDAO.java:53)
at com.arunta.base.db.RecordingMetaDataDAO.persist(RecordingMetaDataDAO.java:68)
at com.arunta.dom.recorder.Recorder.addToDatabase(Recorder.java:2137)
at com.arunta.dom.recorder.Recorder.finalizeRecording(Recorder.java:1981)
at com.arunta.dom.recorder.Recorder.handleCallComplete(Recorder.java:889)
at com.arunta.dom.telephony.CallEventListenerRegistrar.notifyCallComplete(CallEventListenerRegistrar.java:280)
at com.arunta.dom.telephony.voip.EventListenerRegistrar.notifyCallComplete(EventListenerRegistrar.java:126)
at com.arunta.dom.telephony.voip.passive.SipCall$CompletedState.onEntry(SipCall.java:1115)
at com.arunta.dom.telephony.voip.passive.SipCall$FSM.setState(SipCall.java:1201)
at com.arunta.dom.telephony.voip.passive.SipCall$FSM.handleResponse(SipCall.java:1146)
at com.arunta.dom.telephony.voip.passive.SipCall.processMessage(SipCall.java:107)
at com.arunta.dom.telephony.voip.passive.SipCallManager.processPacket(SipCallManager.java:234)
at com.arunta.dom.telephony.voip.NetworkConnector.processPackets(NetworkConnector.java:193)
at com.arunta.dom.telephony.voip.passive.SnifferProvider$1.run(SnifferProvider.java:180)
at com.arunta.tech.timer.TimerTaskWrapper.run(TimerTaskWrapper.java:44)
at com.arunta.tech.timer.TimerThread.mainLoop(Timer.java:480)
at com.arunta.tech.timer.TimerThread.run(Timer.java:423)
Caused by: com.objectdb.o.InternalException
at com.objectdb.o.InternalException.f(InternalException.java:236)
at com.objectdb.o.IPW.an(IPW.java:123)
at com.objectdb.o.PGW.ai(PGW.java:201)
at com.objectdb.o.UPT.G(UPT.java:258)
at com.objectdb.o.UPT.m(UPT.java:172)
at com.objectdb.o.TSK.k(TSK.java:183)
at com.objectdb.o.TSK.i(TSK.java:156)
at com.objectdb.o.TSK.f(TSK.java:95)
at com.objectdb.o.UPT.s(UPT.java:157)
at com.objectdb.o.PGT.q(PGT.java:109)
at com.objectdb.o.UPT.C(UPT.java:121)
at com.objectdb.o.URT.l(URT.java:171)
at com.objectdb.o.TSK.i(TSK.java:145)
at com.objectdb.o.TSK.f(TSK.java:95)
at com.objectdb.o.TSM.e(TSM.java:86)
at com.objectdb.o.UTT.A(UTT.java:365)
at com.objectdb.o.UTT.l(UTT.java:218)
at com.objectdb.o.TSK.i(TSK.java:145)
at com.objectdb.o.TSK.f(TSK.java:95)
at com.objectdb.o.TSM.e(TSM.java:86)
at com.objectdb.o.MST.Vh(MST.java:1356)
at com.objectdb.o.WRA.Vh(WRA.java:396)
at com.objectdb.o.WSM.Vh(WSM.java:184)
at com.objectdb.o.OBM.bP(OBM.java:930)
at com.objectdb.o.OBM.bN(OBM.java:835)
at com.objectdb.o.OBM.bL(OBM.java:740)
at com.objectdb.jpa.EMImpl.commit(EMImpl.java:299)
... 17 more

 

It will be beneficial to us to know if time change, in particular back one hour, may have impact on the operation of Object DB.

I'll post additional information if and when it becomes available.

Regards

Emil

 

#4

Thank you for these new details. As you noticed it seems to be related to the clock move.

ObjectDB organizes data in BTree structures. A BTree is always ordered by a key. The Doctor messages indicate that this order was broken in several BTrees (apparently BTrees that contain time based indexed data).

It is unclear yet how exactly this happened.

ObjectDB Support
#5

Apparently we found the bug, which affects indexes on pure Date fields (i.e. date with no time).

ObjectDB converts pure date values between local time and UTC more than once during transaction commit, and on clock move during commit different values can be obtained for the same field. Hopefully a new build that fixes this bug will be released soon. Thank you very much for this report.

ObjectDB Support
#6

Build 2.6.4_02 should fix this issue.

ObjectDB Support
#7

Thank you for making a build that contains the fix available. We will test.

However, can you give us a a bit more details on how the corruption actually happens? We wish to understand this so we can look for ways to avoid in the future. At minimum we assume that records are being added to the DB at the time of the time change. However, what values in the date fields will cause the corruption? An example would be beneficial.

Also, can we assume that all version prior to 2.6.4_02 have this problem? In particular version 2.5.5_14 and 2.6.1_05?

Thank you

Emil

#8

> However, can you give us a a bit more details on how the corruption actually happens?

It could happen if during writing a pure date (with no time) to the database the TimeZone.getOffset method changes. It could be any date, but the index will become corrupted only if the date is written in different levels of the BTree (most records are written only to the BTree leaf pages) and the change of the offset is between these write operations, i.e. different levels of the BTree hold different values. It could only happen at the moment in which TimeZone.getOffset changes for the active time zone.

Rebuilding the database file with the ObjectDB Doctor (which rebuilds all indexes) should fix the corrupted indexes.

> Also, can we assume that all version prior to 2.6.4_02 have this problem? In particular version 2.5.5_14 and 2.6.1_05?

Probably yes.

ObjectDB Support
#9

This problem is back in 2.6.5.

A  quick test of 2.6.4_08 shows that the problem does not exist in the 2.6.4_08 release. However, same tests show that it exists in 2.6.4_12 (and of course 2.6.5).

 

The delete query we run is:

DELETE FROM RecordingMetaData

The exception is the same:

[ObjectDB 2.6.5] Unexpected exception (Error 990)
  Generated by Java HotSpot(TM) 64-Bit Server VM 1.7.0_80 (on Linux 2.6.32-279.9.1.el6.x86_64).
Please report this error on http://www.objectdb.com/database/issue/new
com.objectdb.o.InternalException: null
com.objectdb.o.InternalException
        at com.objectdb.o.InternalException.f(InternalException.java:236)
        at com.objectdb.o.SPW.an(SPW.java:109)
        at com.objectdb.o.PGW.aj(PGW.java:220)
        at com.objectdb.o.UPT.C(UPT.java:134)
        at com.objectdb.o.UPT.l(UPT.java:110)
        at com.objectdb.o.TSK.i(TSK.java:145)
        at com.objectdb.o.TSK.f(TSK.java:95)
        at com.objectdb.o.UPT.s(UPT.java:157)
        at com.objectdb.o.PGT.q(PGT.java:109)
        at com.objectdb.o.UPT.C(UPT.java:121)
        at com.objectdb.o.UPT.l(UPT.java:110)
        at com.objectdb.o.TSK.i(TSK.java:145)
        at com.objectdb.o.TSK.f(TSK.java:95)
        at com.objectdb.o.UPT.s(UPT.java:157)
        at com.objectdb.o.PGT.q(PGT.java:109)
        at com.objectdb.o.UPT.C(UPT.java:121)
        at com.objectdb.o.URT.l(URT.java:171)
        at com.objectdb.o.TSK.i(TSK.java:145)
        at com.objectdb.o.TSK.f(TSK.java:95)
        at com.objectdb.o.TSM.e(TSM.java:86)
        at com.objectdb.o.UTT.A(UTT.java:370)
        at com.objectdb.o.UTT.l(UTT.java:223)
        at com.objectdb.o.TSK.i(TSK.java:145)
        at com.objectdb.o.TSK.f(TSK.java:95)
        at com.objectdb.o.MST.Vr(MST.java:1337)
        at com.objectdb.o.PRG.ak(PRG.java:952)
        at com.objectdb.o.PRG.ag(PRG.java:659)
        at com.objectdb.o.PRG.af(PRG.java:553)
        at com.objectdb.o.QRM.Vm(QRM.java:286)
        at com.objectdb.o.MST.Vm(MST.java:988)
        at com.objectdb.o.WRA.Vm(WRA.java:311)
        at com.objectdb.o.WSM.Vm(WSM.java:115)
        at com.objectdb.o.QRR.g(QRR.java:247)
        at com.objectdb.o.QRR.f(QRR.java:153)
        at com.objectdb.jpa.JpaQuery.executeUpdate(JpaQuery.java:776)
        at com.objectdb.o.QRP.L(QRP.java:251)
        at com.objectdb.o.QRP.T(QRP.java:723)
        at com.objectdb.o.QRP.actionPerformed(QRP.java:686)
        at javax.swing.AbstractButton.fireActionPerformed(AbstractButton.java:2018)
        at javax.swing.AbstractButton$Handler.actionPerformed(AbstractButton.java:2341)
        at javax.swing.DefaultButtonModel.fireActionPerformed(DefaultButtonModel.java:402)
        at javax.swing.DefaultButtonModel.setPressed(DefaultButtonModel.java:259)
        at javax.swing.plaf.basic.BasicButtonListener.mouseReleased(BasicButtonListener.java:252)
        at java.awt.Component.processMouseEvent(Component.java:6516)
        at javax.swing.JComponent.processMouseEvent(JComponent.java:3321)
        at java.awt.Component.processEvent(Component.java:6281)
        at java.awt.Container.processEvent(Container.java:2229)
        at java.awt.Component.dispatchEventImpl(Component.java:4872)
        at java.awt.Container.dispatchEventImpl(Container.java:2287)
        at java.awt.Component.dispatchEvent(Component.java:4698)
        at java.awt.LightweightDispatcher.retargetMouseEvent(Container.java:4832)
        at java.awt.LightweightDispatcher.processMouseEvent(Container.java:4492)
        at java.awt.LightweightDispatcher.dispatchEvent(Container.java:4422)
        at java.awt.Container.dispatchEventImpl(Container.java:2273)
        at java.awt.Window.dispatchEventImpl(Window.java:2719)
        at java.awt.Component.dispatchEvent(Component.java:4698)
        at java.awt.EventQueue.dispatchEventImpl(EventQueue.java:747)
        at java.awt.EventQueue.access$300(EventQueue.java:103)
        at java.awt.EventQueue$3.run(EventQueue.java:706)
        at java.awt.EventQueue$3.run(EventQueue.java:704)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.security.ProtectionDomain$1.doIntersectionPrivilege(ProtectionDomain.java:76)
        at java.security.ProtectionDomain$1.doIntersectionPrivilege(ProtectionDomain.java:87)
        at java.awt.EventQueue$4.run(EventQueue.java:720)
        at java.awt.EventQueue$4.run(EventQueue.java:718)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.security.ProtectionDomain$1.doIntersectionPrivilege(ProtectionDomain.java:76)
        at java.awt.EventQueue.dispatchEvent(EventQueue.java:717)
        at java.awt.EventDispatchThread.pumpOneEventForFilters(EventDispatchThread.java:242)
        at java.awt.EventDispatchThread.pumpEventsForFilter(EventDispatchThread.java:161)
        at java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:150)
        at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:146)
        at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:138)
        at java.awt.EventDispatchThread.run(EventDispatchThread.java:91)

 

To reproduce the problem:

1. Start the application for the first time so it creates the DB file. The system is in time zone A (we used Australia/Sydney).

2. Before adding any records to the DB change the system time zone to B (we used Australia/Brisbane which is 1 hour back from Australia/Sydney). The time change appares  to be irrelevant as the problem happens if you start the app for the first time in the Australia/Brisbane time zone as well - I am listing it here as that is what we did during testing. In summary, the problem happens even if you start the app for the fisrt time in the actual day light saving time zone.

3. Add records - as you can see from the attached DB file we added about 30K records over 2 days.

4. Try a DELETE - exception thrown. Restarting the application does not help.

 

Also, dbDoctor does not fix the problem. You can verify this by running it on the DB file. We get:

[root@localhost totalrecall]# ./dbDoctor.sh db/SystemDB.odb.2.6.5 db/SystemDB.odb.new.1
ObjectDB Doctor [version 2.6.5]
Copyright (c) 2015, ObjectDB Software. All rights reserved.

Scanning the database file...
.................................................. 100MB
.................................................. 200MB
.................................................. 300MB
.................................................. 400MB
.................................................. 500MB
.................................................. 600MB
.................................................. 700MB
.................................................. 800MB
.................................................. 900MB
.................................................. 1000MB
........... 1024MB (total)

Analyzing database structure...
10% 20% 30% 40% 50% 60% 70% 80% 90% 100%

Page Relation Errors
--------------------

[1] Page #2684 first key is (2016-01-02 09:00:00,1970-01-02 13:05:42,null,null)|1:19940, parent page #5599 key is (2016-01-02 09:00:00,1970-01-03 11:41:54)
[2] Page #3457 first key is (2016-01-02 09:00:00,1970-01-02 13:08:46,'sip:[email protected]:5060','sip:[email protected]:5062')|1:19986, parent page #5863 key is (2016-01-02 09:00:00,1970-01-03 11:44:58)
[3] Page #3735 first key is (2016-01-02 09:00:00,1970-01-02 13:05:42,20)|1:19940, parent page #6142 key is (2016-01-02 09:00:00,1970-01-03 11:41:54)
[4] Page #5598 first key is (2016-01-02 09:00:00,1970-01-02 17:31:13,null,null)|1:23466, parent page #2686 key is (2016-01-02 09:00:00,1970-01-03 16:07:25)
[5] Page #6000 first key is (2016-01-02 09:00:00,1970-01-02 17:35:17,'sip:[email protected]:5060','sip:[email protected]:5062')|1:23527, parent page #3462 key is (2016-01-02 09:00:00,1970-01-03 16:11:29)
[6] Page #6141 first key is (2016-01-02 09:00:00,1970-01-02 17:31:13,26)|1:23466, parent page #3737 key is (2016-01-02 09:00:00,1970-01-03 16:07:25)
[7] Page #6359 first key is 1970-01-02 17:29:01|1:23433, parent page #4057 key is 1970-01-03 16:05:13

Page Content Errors
-------------------

[1] Page #2619 has unsorted entries
[2] Page #2652 has unsorted entries
[3] Page #2686 has unsorted entries
[4] Page #2686 has unsorted entries
[5] Page #2688 has unsorted entries
[6] Page #2688 has unsorted entries
[7] Page #3161 has unsorted entries
[8] Page #3313 has unsorted entries
[9] Page #3461 has unsorted entries
[10] Page #3462 has unsorted entries
[11] Page #3462 has unsorted entries
[12] Page #3670 has unsorted entries
[13] Page #3703 has unsorted entries
[14] Page #3737 has unsorted entries
[15] Page #3737 has unsorted entries
[16] Page #4057 has unsorted entries
[17] Page #4057 has unsorted entries
[18] Page #4057 has unsorted entries
[19] Page #4127 has unsorted entries
[20] Page #4161 has unsorted entries
[21] Page #5599 has unsorted entries
[22] Page #5599 has unsorted entries
[23] Page #5863 has unsorted entries
[24] Page #6142 has unsorted entries
[25] Page #6142 has unsorted entries

Creating a database copy...
.  30335 entity objects (total) have been migrated.

New database copy is ready at: db/SystemDB.odb.new.1

 

Emil

#10

Test case that demonstrates the problem.

We run it on a Linux machine with ObjectDB 2.6.5 and AEDT time zone:

[root@trvr-200]# uname -a

Linux localhost 2.6.32-279.9.1.el6.x86_64 #1 SMP Tue Sep 25 21:43:11 UTC 2012 x86_64 x86_64 x86_64 GNU/Linux

 

package test;

import java.text.ParseException;
import java.text.SimpleDateFormat;
import java.util.Calendar;
import java.util.Date;

import javax.jdo.annotations.Index;
import javax.jdo.annotations.Indices;
import javax.persistence.Basic;
import javax.persistence.Entity;
import javax.persistence.EntityManager;
import javax.persistence.EntityManagerFactory;
import javax.persistence.GeneratedValue;
import javax.persistence.GenerationType;
import javax.persistence.Id;
import javax.persistence.Persistence;
import javax.persistence.Query;
import javax.persistence.SequenceGenerator;
import javax.persistence.Temporal;
import javax.persistence.TemporalType;
import javax.persistence.Version;

public class DeleteTest {
   
    public static void main(String[] args)  {
        SimpleDateFormat dtf = new SimpleDateFormat("yyyy.MM.dd HH:mm:ss");
       
        EntityManagerFactory emf =
            Persistence.createEntityManagerFactory(
                "objectdb:$objectdb/deleteme/test.tmp;drop");
        EntityManager em = emf.createEntityManager();

        em.getTransaction().begin();
       
        // Add records
        DateTime dt = null;
        try {
            dt = new DateTime(dtf.parse("2015.10.31 09:18:14"), new Short((short)10), null, "121 Jerry");
            em.persist(dt);
        }
        catch (ParseException e) {
            e.printStackTrace();
        }
        try {
            dt = new DateTime(dtf.parse("2015.12.09 10:59:57"), new Short((short)10), null, "121 Jerry");
            em.persist(dt);
        }
        catch (ParseException e) {
            e.printStackTrace();
        }
        try {
            dt = new DateTime(dtf.parse("2015.12.10 12:46:28"), new Short((short)19), "280152151", "145 Annex 2");
            em.persist(dt);
        }
        catch (ParseException e) {
            e.printStackTrace();
        }
        try {
            dt = new DateTime(dtf.parse("2015.12.10 12:50:05"), new Short((short)19), "280152151", "145 Annex 2");
            em.persist(dt);
        }
        catch (ParseException e) {
            e.printStackTrace();
        }
        try {
            dt = new DateTime(dtf.parse("2015.12.10 12:41:37"), new Short((short)19), "280152151", "145 Annex 2");
            em.persist(dt);
        }
        catch (ParseException e) {
            e.printStackTrace();
        }
        try {
            dt = new DateTime(dtf.parse("2015.12.10 10:59:58"), new Short((short)10), null, "121 Jerry");
            em.persist(dt);
        }
        catch (ParseException e) {
            e.printStackTrace();
        }
        try {
            dt = new DateTime(dtf.parse("2015.12.10 13:24:58"), new Short((short)10), "9512711789", "121 Jerry");
            em.persist(dt);
        }
        catch (ParseException e) {
            e.printStackTrace();
        }
        try {
            dt = new DateTime(dtf.parse("2015.12.10 13:26:19"), new Short((short)10), "9512711789", "121 Jerry");
            em.persist(dt);
        }
        catch (ParseException e) {
            e.printStackTrace();
        }
        try {
            dt = new DateTime(dtf.parse("2015.12.12 15:55:07"), new Short((short)19), null, "144 Annex 1");
            em.persist(dt);
        }
        catch (ParseException e) {
            e.printStackTrace();
        }
        try {
            dt = new DateTime(dtf.parse("2015.12.15 09:43:55"), new Short((short)7), null, null);
            em.persist(dt);
        }
        catch (ParseException e) {
            e.printStackTrace();
        }
        try {
            dt = new DateTime(dtf.parse("2015.12.15 09:43:55"), new Short((short)8), null, null);
            em.persist(dt);
        }
        catch (ParseException e) {
            e.printStackTrace();
        }
        
        em.getTransaction().commit();

        Query q = em.createQuery("SELECT COUNT(r) FROM DateTime AS r");
        em.getTransaction().begin();
        Long r = (Long) q.getSingleResult();
        em.getTransaction().commit();
       
        System.out.println("TOTAL RECORDS (before delete): " + r.longValue());
       
        System.out.println("REMOVING ALL RECORDS");

        try {
            q = em.createQuery("DELETE FROM DateTime");
            em.getTransaction().begin();
            q.executeUpdate();
            em.getTransaction().commit();
        }
        catch (Throwable t) {
            t.printStackTrace();
           
            if (em.getTransaction().isActive())
                em.getTransaction().rollback();
        }

        q = em.createQuery("SELECT COUNT(r) FROM DateTime AS r");
        em.getTransaction().begin();
        r = (Long) q.getSingleResult();
        em.getTransaction().commit();
       
        System.out.println("TOTAL RECORDS (after delete): " + r.longValue());

        em.close();
        emf.close();
    }

    public static Date getTimeOf(Date date) {
        Date rondedDate = roundDownDateTime(date);
       
        Calendar calendar = Calendar.getInstance();
        calendar.setTime(rondedDate);
       
        calendar.set(Calendar.YEAR, 1970);
        calendar.set(Calendar.MONTH, Calendar.JANUARY);
        calendar.set(Calendar.DAY_OF_MONTH, 1);
       
        return calendar.getTime();
    }

    public static Date getDateOf(Date date) {
        Calendar calendar = Calendar.getInstance();
        calendar.setTime(date);
       
        calendar.set(Calendar.MILLISECOND, 0);
        calendar.set(Calendar.SECOND, 0);
        calendar.set(Calendar.MINUTE, 0);
        calendar.set(Calendar.HOUR, 0);
       
        return calendar.getTime();
    }

    public static Date roundDownDateTime(Date dateTime) {
        long dateTimeMs = dateTime.getTime();
        long reminderMs  = dateTimeMs % 1000;
        dateTimeMs -= reminderMs;
        return new Date(dateTimeMs);
    }

    @Entity(name="DateTime")
    @SequenceGenerator(
        name="DateTime_sequence",
        sequenceName="DateTime_sequence",
        allocationSize=1
    )
    @Indices({
        // Indices for popular searches
        @Index(members={"startDate", "startTime", "channelNumber"}),

        @Index(members={"startDate"}),
        @Index(members={"startTime"}),

        @Index(members={"startDate", "mapToCli", "mapFromCli"}),
        @Index(members={"startDate", "startTime", "mapToCli", "mapFromCli"}),
    })
    public static class DateTime {
        private Long id;
        private Long version;

        private Date startDateTime;     // Time stamp: start of recording in local time zone
        private Date startDate;         // Date: date part of startDateTime
        private Date startTime;         // Time: time part of startDateTime

        private Short channelNumber;

        private String mapToCli;
        private String mapFromCli;

        public DateTime(Date d, Short channelNumber, String mapToCli, String mapFromCli) {
            setStartDateTime(new Date(d.getTime()));
            setStartDate(getDateOf(d));
            setStartTime(getTimeOf(d));
            setChannelNumber(channelNumber);
            setMapToCli(mapToCli);
            setMapFromCli(mapFromCli);
         }
       
        public boolean equals(Object o) {
            if (this == o) {
                return true;
            }
            if ((o == null) || !(o instanceof DateTime)) {
                return false;
            }
            if (id == null) {
                return false;
            }

            DateTime other = (DateTime)o;
            return id.equals(other.getId()) && version.equals(other.getVersion());
        }

        public int hashCode() {
            if (id != null) {
                return id.hashCode();
            }
            else {
                return super.hashCode();
            }
        }
       
        @Id
        @GeneratedValue(strategy=GenerationType.SEQUENCE, generator="DateTime_sequence")
        public Long getId() {
            return id;
        }

        public void setId(Long id) {
            this.id = id;
        }

        @Version
        public Long getVersion() {
            return version;
        }

        public void setVersion(Long version) {
            this.version = version;
        }

        @Basic(optional = false)
        @Temporal(TemporalType.TIMESTAMP)
        public Date getStartDateTime() {
            return startDateTime;
        }

        public void setStartDateTime(Date startDateTime) {
            this.startDateTime = startDateTime;
        }

        @Basic(optional = false)
        @Temporal(TemporalType.DATE)
        public Date getStartDate() {
            return startDate;
        }

        public void setStartDate(Date startDate) {
            this.startDate = startDate;
        }

        @Basic(optional = false)
        @Temporal(TemporalType.TIME)
        public Date getStartTime() {
            return startTime;
        }

        public void setStartTime(Date startTime) {
            this.startTime = startTime;
        }
       
        @Basic(optional = false)
        public Short getChannelNumber() {
            return channelNumber;
        }

        public void setChannelNumber(Short channelNumber) {
            this.channelNumber = channelNumber;
        }

        @Basic
        public String getMapToCli() {
            return mapToCli;
        }

        public void setMapToCli(String mapToCli) {
            this.mapToCli = mapToCli;
        }

        @Basic
        public String getMapFromCli() {
            return mapFromCli;
        }

        public void setMapFromCli(String mapFromCli) {
            this.mapFromCli = mapFromCli;
        }


        @Override
        public String toString() {
            StringBuffer b = new StringBuffer();
            b.append("startDateTime=" + getStartDateTime() + "\n");
            b.append("startDate=" + getStartDate() + "\n");
            b.append("startTime=" + getStartTime() + "\n");
            b.append("channelNumber=" + getChannelNumber() + "\n");
            b.append("mapToCli=" + getMapToCli() + "\n");
            b.append("mapFromCli=" + getMapToCli() + "\n");
            return b.toString();
        }
    }

}

 

The result produced by the test case:

[root@trvr-200]# java -cp javaLibs/objectdb.jar:. test.DeleteTest
TOTAL RECORDS (before delete): 11
REMOVING ALL RECORDS
[ObjectDB 2.6.5] Unexpected exception (Error 990)
  Generated by Java HotSpot(TM) 64-Bit Server VM 1.7.0_80 (on Linux 2.6.32-279.9.1.el6.x86_64).

Please report this error on http://www.objectdb.com/database/issue/new
com.objectdb.o.InternalException: null
com.objectdb.o.InternalException
        at com.objectdb.o.InternalException.f(InternalException.java:236)
        at com.objectdb.o.SPW.an(SPW.java:109)
        at com.objectdb.o.PGW.aj(PGW.java:220)
        at com.objectdb.o.UPT.C(UPT.java:134)
        at com.objectdb.o.URT.l(URT.java:171)
        at com.objectdb.o.TSK.i(TSK.java:145)
        at com.objectdb.o.TSK.f(TSK.java:95)
        at com.objectdb.o.TSM.e(TSM.java:86)
        at com.objectdb.o.UTT.A(UTT.java:370)
        at com.objectdb.o.UTT.l(UTT.java:223)
        at com.objectdb.o.TSK.i(TSK.java:145)
        at com.objectdb.o.TSK.f(TSK.java:95)
        at com.objectdb.o.MST.Vr(MST.java:1337)
        at com.objectdb.o.PRG.ak(PRG.java:952)
        at com.objectdb.o.PRG.ag(PRG.java:659)
        at com.objectdb.o.PRG.af(PRG.java:553)
        at com.objectdb.o.QRM.Vm(QRM.java:286)
        at com.objectdb.o.MST.Vm(MST.java:988)
        at com.objectdb.o.WRA.Vm(WRA.java:311)
        at com.objectdb.o.WSM.Vm(WSM.java:115)
        at com.objectdb.o.QRR.g(QRR.java:247)
        at com.objectdb.o.QRR.f(QRR.java:153)
        at com.objectdb.jpa.JpaQuery.executeUpdate(JpaQuery.java:776)
        at test.DeleteTest.main(DeleteTest.java:134)
TOTAL RECORDS (after delete): 11
[root@trvr-200]#

 

#11

Thank you again for your report and sorry for the inconvenience. Handling pure date and pure time is a bit tricky because of the need to neutralize the effect of the current time zone, keeping the values order, etc. Hopefully build 2.6.5_02 does it correctly.

ObjectDB Support
#12

2.6.5_02 appears to work fine.

Thank you

Reply