gggard / AndroidCaldavSyncAdapater

Caldav synch adapter for Android
246 stars 88 forks source link

Error: "Couldn't read row 337, col 0 from CursorWin..." #119

Closed LudovicRousseau closed 10 years ago

LudovicRousseau commented 10 years ago

In the Android notification I have the error:

"Caldav sync error (general)
Couldn't read row 337, col 0 from CursorWin..."

I do not have the complete error message. I could not find the error message in the source code. I have no real idea of where it comes from. My server is DAViCal. I have an export of the agenda in .ics format

I get it when synchronising a big agenda (1049 entries). So it may be hard to find the record causing the error.

What can I do next?

LudovicRousseau commented 10 years ago

In case it may help, the latest logs in my apache log file are:

freebox - - [02/Oct/2013:21:19:15 +0200] "PROPFIND /davical/ HTTP/1.1" 401 1827 
"-" "CalDAV Sync Adapter (Android) https://github.com/gggard/AndroidCaldavSyncAd
apater Version:1.8"
freebox - test [02/Oct/2013:21:19:15 +0200] "PROPFIND /davical/ HTTP/1.1" 207 15
46 "-" "CalDAV Sync Adapter (Android) https://github.com/gggard/AndroidCaldavSyn
cAdapater Version:1.8"
freebox - test [02/Oct/2013:21:19:15 +0200] "PROPFIND /davical/ HTTP/1.1" 207 97
1 "-" "CalDAV Sync Adapter (Android) https://github.com/gggard/AndroidCaldavSync
Adapater Version:1.8"
freebox - test [02/Oct/2013:21:19:15 +0200] "PROPFIND /davical/caldav.php/test/ 
HTTP/1.1" 207 925 "-" "CalDAV Sync Adapter (Android) https://github.com/gggard/A
ndroidCaldavSyncAdapater Version:1.8"
freebox - test [02/Oct/2013:21:19:16 +0200] "PROPFIND /davical/caldav.php/test/ 
HTTP/1.1" 207 7271 "-" "CalDAV Sync Adapter (Android) https://github.com/gggard/
AndroidCaldavSyncAdapater Version:1.8"
freebox - test [02/Oct/2013:21:19:16 +0200] "PUT /davical/caldav.php/rousseau/ca
lendar/neab79ppvas91sklu99ol0vggk%40googlecom.ics HTTP/1.1" 403 531 "-" "CalDAV 
Sync Adapter (Android) https://github.com/gggard/AndroidCaldavSyncAdapater Versi
on:1.8"
freebox - test [02/Oct/2013:21:19:17 +0200] "PROPFIND /davical/caldav.php/test/7
A9E35CD-B00A-4AF3-A366-C193147026A2/ HTTP/1.1" 207 333672 "-" "CalDAV Sync Adapt
er (Android) https://github.com/gggard/AndroidCaldavSyncAdapater Version:1.8"

And nothing more.

timoberger commented 10 years ago

maybe there are 2 sync working against each other. i am not sure whether this could happen. if a cursor from a selecting source gets invalid, the original source changed and the cursor isn't able to read a valid record set. maybe i didn't see this problem in the past. one of my calendars is growing since some years.

LudovicRousseau commented 10 years ago

2 sync working from 2 different clients ? like my phone and Calendar on OS X? I have different agenda clients talking to the server. But no client where doing a modification at that time (if I am correct).

I already got the error using my real DAViCal server account. So I used a test account to know from which of my agenda the error comes from but adding the agendas one after the other. Of course the problem comes from my biggest agenda.

LudovicRousseau commented 10 years ago

CalDAV Sync Adapter is now looping with these 2 HTTP requests before I get the error:

freebox - test [02/Oct/2013:22:00:05 +0200] "PUT /davical/caldav.php/rousseau/calendar/neab79ppvas91sklu99ol0vggk%40googlecom.ics HTTP/1.1" 403 531 "-" "CalDAV Sync Adapter (Android) https://github.com/gggard/AndroidCaldavSyncAdapater Version:1.8" freebox - test [02/Oct/2013:22:00:05 +0200] "PROPFIND /davical/caldav.php/test/7A9E35CD-B00A-4AF3-A366-C193147026A2/ HTTP/1.1" 207 333672 "-" "CalDAV Sync Adapter (Android) https://github.com/gggard/AndroidCaldavSyncAdapater Version:1.8"

timoberger commented 10 years ago
PUT /davical/caldav.php/rousseau/calendar/neab79ppvas91sklu99ol0vggk%40googlecom.ics
PROPFIND /davical/caldav.php/test/7A9E35CD-B00A-4AF3-A366-C193147026A2/

did you create multiple accounts for the same calendars?

please describe your accounts in details (used credentials, url and the expected calendars)

LudovicRousseau commented 10 years ago

I tried to find if the problem came from 1 special record. So I split my .ics file in two parts to do a dychotomy search. Both half of the file are synchronising fine when they are alone. No error. Then I add the second half of the calendar and I get the same error again.

No, I do not have multiple accounts for the same calendar. Only one account "test".

I then used my USB cable to get some debug.

I/CaldavFacade( 6051): 3 calendars found in set https://xxx.free.fr/davical/caldav.php/test/
I/SyncAdapter( 6051): 3 calendars found at android
I/SyncAdapter( 6051): Detected calendar name=Test user calendar URI=https://xxx.free.fr/davical/caldav.php/test/calendar/
D/SyncAdapter( 6051): CTag has not changed, nothing to do
I/SyncAdapter( 6051): Detected calendar name=Test 2 URI=https://xxx.free.fr/davical/caldav.php/test/F1B5D851-7DC8-477D-A1C5-7CAC8D6F56DC/
D/SyncAdapter( 6051): CTag has not changed, nothing to do
I/SyncAdapter( 6051): Detected calendar name=1 URI=https://xxx.free.fr/davical/caldav.php/test/CEBA3F1E-C093-4DE2-A8EA-494CA2F63DDA/
D/SyncAdapter( 6051): CTag has changed, something to synchronise
D/CaldavFacade( 6051): Getting eTag by PROPFIND at https://xxx.free.fr/davical/caldav.php/test/CEBA3F1E-C093-4DE2-A8EA-494CA2F63DDA/

The 2 first calendars are small and already in sync. The 3rd one is the one with problem.

After I manually start the synchronisation on the AndroidCaldavSyncAdapater I get a lot of logs like:

D/dalvikvm( 6051): GC_FOR_ALLOC freed <1K, 21% free 13658K/17287K, paused 13ms, total 13ms
I/dalvikvm-heap( 6051): Grow heap (frag case) to 15.059MB for 909356-byte allocation
D/dalvikvm( 6051): GC_CONCURRENT freed 0K, 16% free 14546K/17287K, paused 12ms+2ms, total 24ms
D/dalvikvm( 6051): WAIT_FOR_CONCURRENT_GC blocked 6ms
D/dalvikvm( 6051): GC_FOR_ALLOC freed 1184K, 20% free 13954K/17287K, paused 13ms, total 13ms
D/dalvikvm( 6051): GC_CONCURRENT freed 0K, 16% free 14546K/17287K, paused 12ms+1ms, total 24ms
D/dalvikvm( 6051): WAIT_FOR_CONCURRENT_GC blocked 7ms

And also lots of logs like:

I/SyncAdapter( 6051): Event /davical/caldav.php/test/CEBA3F1E-C093-4DE2-A8EA-494CA2F63DDA/palm-datebook-0064d19f-5756aa96-rousseau%40iMac-de-Ludovic-Rousseaulocal.ics androidUri=content://com.android.calendar/events/6179
D/SyncAdapter( 6051): Event compare: "fb31919cd28e43ce7e8a40ecb176dacf" <> "fb31919cd28e43ce7e8a40ecb176dacf"
I/SyncAdapter( 6051): Event /davical/caldav.php/test/CEBA3F1E-C093-4DE2-A8EA-494CA2F63DDA/palm-datebook-0064d56f-5756aa96-rousseau%40iMac-de-Ludovic-Rousseaulocal.ics androidUri=content://com.android.calendar/events/6180
D/SyncAdapter( 6051): Event compare: "55aacf6115bfc2cc8f628f8975acace3" <> "55aacf6115bfc2cc8f628f8975acace3"

Then the Java exception:

E/SQLiteConnection( 3754): startPos 676 > actual rows 35
E/CursorWindow( 3754): Failed to read row 337, column 0 from a CursorWindow which has 0 rows, 66 columns.
E/DatabaseUtils( 3754): Writing exception to parcel
E/DatabaseUtils( 3754): java.lang.IllegalStateException: Couldn't read row 337, col 0 from CursorWindow.  Make sure the Cursor is initialized correctly before accessing data from it.
E/DatabaseUtils( 3754):     at android.database.CursorWindow.nativeGetLong(Native Method)
E/DatabaseUtils( 3754):     at android.database.CursorWindow.getLong(CursorWindow.java:511)
E/DatabaseUtils( 3754):     at android.database.AbstractWindowedCursor.getLong(AbstractWindowedCursor.java:75)
E/DatabaseUtils( 3754):     at android.database.AbstractCursor.moveToPosition(AbstractCursor.java:219)
E/DatabaseUtils( 3754):     at android.database.AbstractCursor.moveToNext(AbstractCursor.java:244)
E/DatabaseUtils( 3754):     at com.android.providers.calendar.CalendarProvider2.handleUpdateEvents(CalendarProvider2.java:4722)
E/DatabaseUtils( 3754):     at com.android.providers.calendar.CalendarProvider2.updateInTransaction(CalendarProvider2.java:5067)
E/DatabaseUtils( 3754):     at com.android.providers.calendar.SQLiteContentProvider.update(SQLiteContentProvider.java:147)
E/DatabaseUtils( 3754):     at android.content.ContentProvider$Transport.update(ContentProvider.java:235)
E/DatabaseUtils( 3754):     at android.content.ContentProviderNative.onTransact(ContentProviderNative.java:203)
E/DatabaseUtils( 3754):     at android.os.Binder.execTransact(Binder.java:367)
E/DatabaseUtils( 3754):     at dalvik.system.NativeStart.run(Native Method)
E/SyncAdapter( 6051): Updating calendar exception java.lang.IllegalStateException
E/SyncAdapter( 6051): java.lang.IllegalStateException: Couldn't read row 337, col 0 from CursorWindow.  Make sure the Cursor is initialized correctly before accessing data from it.
E/SyncAdapter( 6051):   at android.os.Parcel.readException(Parcel.java:1433)
E/SyncAdapter( 6051):   at android.database.DatabaseUtils.readExceptionFromParcel(DatabaseUtils.java:188)
E/SyncAdapter( 6051):   at android.database.DatabaseUtils.readExceptionFromParcel(DatabaseUtils.java:140)
E/SyncAdapter( 6051):   at android.content.ContentProviderProxy.update(ContentProviderNative.java:507)
E/SyncAdapter( 6051):   at android.content.ContentProviderClient.update(ContentProviderClient.java:160)
E/SyncAdapter( 6051):   at org.gege.caldavsyncadapter.caldav.entities.DavCalendar.untagAndroidEvents(DavCalendar.java:500)
E/SyncAdapter( 6051):   at org.gege.caldavsyncadapter.syncadapter.SyncAdapter.synchroniseEvents(SyncAdapter.java:374)
E/SyncAdapter( 6051):   at org.gege.caldavsyncadapter.syncadapter.SyncAdapter.onPerformSync(SyncAdapter.java:170)
E/SyncAdapter( 6051):   at android.content.AbstractThreadedSyncAdapter$SyncThread.run(AbstractThreadedSyncAdapter.java:254)

What can I do next?

jeroenrnl commented 10 years ago

I have the same issue, with Baikal Calender server.

Running the Caldav Sync version release 28/10

The error is "Couldn't read row 683, col 0 from Cursor..."

LudovicRousseau commented 10 years ago

@jeroenrnl do you have "a lot" of appointment in your calendar? I suspect a limited capacity issue in AndroidCaldavSyncAdapater.

jeroenrnl commented 10 years ago

Yes, 2372, according to Baikal. However, I did not have any problem with the previous version of CalDav Sync.

timoberger commented 10 years ago

@jeroenrnl @LudovicRousseau are you able to provides these calendars (or their sources) as a single ics-file to me?

LudovicRousseau commented 10 years ago

I wanted to generate an anonymized version of my calendar in .ICS for you. But have not yet worked on it. I will try to provide that soon.

LudovicRousseau commented 10 years ago

@timoberger where can I send you my 90KB .ics file?

timoberger commented 10 years ago

timoberger@users.sourceforge.net

LudovicRousseau commented 10 years ago

.ICS file sent.

timoberger commented 10 years ago

this is sad. all 1048 events synced without any trouble. according to your debug output the error occures during "untagAndroidEvents"

E/SyncAdapter( 6051):   at org.gege.caldavsyncadapter.caldav.entities.DavCalendar.untagAndroidEvents(DavCalendar.java:500)

i need more details:

LudovicRousseau commented 10 years ago

Samsung Galaxy note 2 GT-N7100 Android 4.1.2 from Samsung (no local changes) davical 1.1.1-1 from Debian stable AndroidCaldavSyncAdapater version 1.8

timoberger commented 10 years ago

@jeroenrnl you both are using different server. i would guess that you are using the same device?

jeroenrnl commented 10 years ago

@timoberger No, I am using an HTC One X, running Android 4.2.2

The problem only seems to exist when I change an item on my phone. As soon as I delete the changed item on my phone, synchronization works.

timoberger commented 10 years ago

@jeroenrnl you are not able to edit any event? only deletion is possible?

jeroenrnl commented 10 years ago

@timoberger I was jumping to conclusions, I had assumed that, because the error sometimes wouldn't appear for hours that it was syncing correctly, but I now found out it wasn't.

jeroenrnl commented 10 years ago

I have done a little test: created a second calendar on the same server, for the same user and that works fine. If I create an item in Thunderbird, it appears on my phone and if I create an item on my phone, it appears on Thunderbird...

timoberger commented 10 years ago

i need some debug output, a network dump, access to the calendar or something else.

timoberger commented 10 years ago

@jeroenrnl are you able to provide some debuggin informations?

jeroenrnl commented 10 years ago

@timoberger I am trying to get some debug info, my server works over https, so I have to reconfigure it to http to get any readable tcpdump output

jeroenrnl commented 10 years ago

I still have quite some trouble getting the initial sync to work, I'd like it to be in sync before I try to break it, so the amount of data being exchanged is limited. However, I have been able to make some captures of moments where things fail and I noticed quite a few "404 not founds" in the data stream, I wouldn't assume they would normally be part of a sync, correct?

jeroenrnl commented 10 years ago

@timoberger I have mailed you a wireshark trace (pcap) of my sync. I looked through it, but it seems to be completing the session and I can't find anything where it goes wrong. I hope it helps you to locate the culprit.

Thanks

jeroenrnl commented 10 years ago

By the way, the error may have something to do with either reading from an Android Calender: http://stackoverflow.com/questions/16563934/couldnt-read-row-384-col-47-from-cursorwindow-make-sure-the-cursor-is-initial or SQLite: http://stackoverflow.com/questions/17207681/couldnt-read-row-1-col-1-from-cursorwindow

timoberger commented 10 years ago

i will change the way of untagging events. every event gets an unique tag number. and the tag will be reseted in steps of 100 (or something appropriate that fits your needs).

timoberger commented 10 years ago

please test my latest release v1.8.1-beta.2 https://github.com/timoberger/AndroidCaldavSyncAdapater/releases/tag/v1.8.1-beta.2

LudovicRousseau commented 10 years ago

I installed v1.8.1-beta.2 and redid the same test. The sync finished with no error. Great!

It looks like the bug is fixed. I close it. Thanks.