[TD-73] Duplicate Annotations Crash Taskd

[taskwarrior]

Jack on 2014-09-03T05:29:00Z says:

Here is another case of a particular account with duplicated annotations that causes taskd to crash.

Here is a snippet from taskd.log showing a sync that causes taskd to crash:

{code} 2014-09-02 20:37:53 [1] 'sync' from 'FreeCinc/freecinc_**' using 'task 2.3.0' at :0 2014-09-02 20:37:53 [1] Client key '[filtered]' 8 2014-09-02 20:37:53 [1] Loaded 46814 records 2014-09-02 20:37:53 [1] Branch point: 093c3a9d-b789-43f7-929e-b72f64db25da --> 22829 2014-09-02 20:37:57 [1] Subset 23745 tasks 2014-09-02 20:38:00 [1] applying right 1408824020 >= 1408819729 2014-09-02 20:38:00 [1] patch modify modified=1408819729 2014-09-02 20:38:00 [1] applying right 1408824020 >= 1408820756 2014-09-02 20:38:00 [1] patch modify modified=1408820756 2014-09-02 20:38:00 [1] applying right 1408824020 >= 1408822011 2014-09-02 20:38:00 [1] patch modify modified=1408822011 2014-09-02 20:38:00 [1] applying right 1408824020 >= 1408823490 2014-09-02 20:38:00 [1] patch modify modified=1408823490 2014-09-02 20:38:00 [1] applying left 1408824020 < 1408824613 2014-09-02 20:38:00 [1] patch add end=1408824020 2014-09-02 20:38:00 [1] patch modify modified=1408824020 2014-09-02 20:38:00 [1] patch modify status=deleted 2014-09-02 20:38:00 [1] patch modify modified=1408824613 2014-09-02 20:38:00 [1] patch modify modified=1408827082 2014-09-02 20:38:00 [1] patch modify modified=1408828624 2014-09-02 20:38:00 [1] patch modify modified=1408829759 2014-09-02 20:38:00 [1] patch modify modified=1408831013 2014-09-02 20:38:00 [1] patch modify modified=1408832193 2014-09-02 20:38:00 [1] patch modify modified=1408834613 2014-09-02 20:38:00 [1] patch modify modified=1408835824 2014-09-02 20:38:00 [1] patch modify modified=1408837417 2014-09-02 20:38:00 [1] patch modify modified=1408839853 2014-09-02 20:38:00 [1] patch modify modified=1408842551 2014-09-02 20:38:00 [1] patch modify modified=1408910370 2014-09-02 20:38:00 [1] patch modify modified=1408912428 2014-09-02 20:38:00 [1] patch modify modified=1408914387 2014-09-02 20:38:00 [1] patch modify modified=1408916078 2014-09-02 20:38:00 [1] patch modify modified=1408917525 2014-09-02 20:38:00 [1] patch modify modified=1408919249 2014-09-02 20:38:00 [1] patch modify modified=1408920239 2014-09-02 20:38:00 [1] patch modify modified=1408922267 2014-09-02 20:38:00 [1] patch modify modified=1408924259 2014-09-02 20:38:00 [1] patch modify modified=1408925636 2014-09-02 20:38:00 [1] patch modify modified=1408926987 2014-09-02 20:38:00 [1] patch modify modified=1408928869 2014-09-02 20:38:00 [1] patch modify modified=1408931931 2014-09-02 20:38:00 [1] patch modify modified=1408933121 2014-09-02 20:38:00 [1] patch modify modified=1408934662 2014-09-02 20:38:00 [1] patch modify modified=1408936354 2014-09-02 20:38:00 [1] patch modify modified=1408937787 2014-09-02 20:38:00 [1] patch modify modified=1408939957 2014-09-02 20:38:00 [1] patch modify modified=1408940984 2014-09-02 20:38:00 [1] patch modify modified=1408943090 2014-09-02 20:38:00 [1] patch modify modified=1408944986 2014-09-02 20:38:00 [1] patch modify modified=1408946299 2014-09-02 20:38:00 [1] patch modify modified=1408948128 2014-09-02 20:38:00 [1] patch modify modified=1408949983 2014-09-02 20:38:00 [1] patch modify modified=1408951782 2014-09-02 20:38:00 [1] patch modify modified=1408953830 2014-09-02 20:38:00 [1] patch modify modified=1408954899 2014-09-02 20:38:00 [1] patch modify modified=1408957968 2014-09-02 20:38:00 [1] patch modify modified=1408959007 2014-09-02 20:38:00 [1] patch modify modified=1408961557 2014-09-02 20:38:00 [1] patch modify modified=1408963438 2014-09-02 20:38:00 [1] patch modify modified=1408965157 2014-09-02 20:38:00 [1] patch modify modified=1408967058 2014-09-02 20:38:00 [1] patch modify modified=1408969131 2014-09-02 20:38:00 [1] patch modify modified=1408971117 2014-09-02 20:38:00 [1] patch modify modified=1408972356 2014-09-02 20:38:00 [1] patch modify modified=1408974982 2014-09-02 20:38:00 [1] patch modify modified=1408975954 2014-09-02 20:38:00 [1] patch modify modified=1408977769 2014-09-02 20:38:00 [1] patch modify modified=1408979328 2014-09-02 20:38:00 [1] patch modify modified=1408980594 2014-09-02 20:38:00 [1] patch modify modified=1408982254 2014-09-02 20:38:00 [1] patch modify modified=1408983688 2014-09-02 20:38:00 [1] patch modify modified=1408985972 2014-09-02 20:38:00 [1] patch modify modified=1408987251 2014-09-02 20:38:00 [1] patch modify modified=1408990292 2014-09-02 20:38:00 [1] patch modify modified=1408990434 2014-09-02 20:38:00 [1] patch modify modified=1408992155 2014-09-02 20:38:00 [1] patch modify modified=1408993238 2014-09-02 20:38:00 [1] patch modify modified=1408994864 2014-09-02 20:38:00 [1] patch modify modified=1408996276 2014-09-02 20:38:00 [1] patch modify modified=1408997522 2014-09-02 20:38:00 [1] patch modify modified=1408998985 2014-09-02 20:38:00 [1] patch modify modified=1409000237 2014-09-02 20:38:00 [1] patch modify modified=1409002038 2014-09-02 20:38:00 [1] patch modify modified=1409003149 2014-09-02 20:38:00 [1] patch modify modified=1409088989 2014-09-02 20:38:00 [1] patch modify modified=1409090771 2014-09-02 20:38:00 [1] patch modify modified=1409092590 2014-09-02 20:38:00 [1] patch modify modified=1409093851 2014-09-02 20:38:00 [1] patch modify modified=1409095288 2014-09-02 20:38:00 [1] patch modify modified=1409096795 2014-09-02 20:38:00 [1] patch modify modified=1409098446 2014-09-02 20:38:00 [1] patch modify modified=1409101054 2014-09-02 20:38:00 [1] patch modify modified=1409102083 2014-09-02 20:38:00 [1] patch modify modified=1409103760 2014-09-02 20:38:00 [1] patch modify modified=1409105188 2014-09-02 20:38:00 [1] patch modify modified=1409107361 2014-09-02 20:38:00 [1] patch modify modified=1409109515 2014-09-02 20:38:00 [1] patch modify modified=1409111087 2014-09-02 20:38:00 [1] patch modify modified=1409112390 2014-09-02 20:38:00 [1] patch modify modified=1409114283 2014-09-02 20:38:00 [1] patch modify modified=1409115562 2014-09-02 20:38:00 [1] patch modify modified=1409116743 2014-09-02 20:38:00 [1] patch modify modified=1409119590 2014-09-02 20:38:00 [1] patch modify modified=1409122638 2014-09-02 20:38:00 [1] patch modify modified=1409123925 2014-09-02 20:38:00 [1] patch modify modified=1409126256 2014-09-02 20:38:00 [1] patch modify modified=1409127521 2014-09-02 20:38:00 [1] patch modify modified=1409128958 2014-09-02 20:38:00 [1] patch modify modified=1409131120 2014-09-02 20:38:00 [1] patch modify modified=1409133457 2014-09-02 20:38:00 [1] patch modify modified=1409134751 2014-09-02 20:38:00 [1] patch modify modified=1409136159 2014-09-02 20:38:00 [1] patch modify modified=1409138320 2014-09-02 20:38:00 [1] patch modify modified=1409140655 2014-09-02 20:38:00 [1] patch modify modified=1409141942 2014-09-02 20:38:00 [1] patch modify modified=1409143354 2014-09-02 20:38:00 [1] patch modify modified=1409144826 2014-09-02 20:38:00 [1] patch modify modified=1409146055 2014-09-02 20:38:00 [1] patch modify modified=1409148035 2014-09-02 20:38:00 [1] patch modify modified=1409149135 2014-09-02 20:38:00 [1] patch modify modified=1409150759 2014-09-02 20:38:00 [1] patch modify modified=1409152743 2014-09-02 20:38:00 [1] patch modify modified=1409154686 2014-09-02 20:38:00 [1] patch modify modified=1409156836 2014-09-02 20:38:00 [1] patch modify modified=1409158597 2014-09-02 20:38:00 [1] patch modify modified=1409160942 2014-09-02 20:38:00 [1] patch modify modified=1409161885 2014-09-02 20:38:00 [1] patch modify modified=1409163250 2014-09-02 20:38:00 [1] patch modify modified=1409165205 2014-09-02 20:38:00 [1] patch modify modified=1409167196 2014-09-02 20:38:00 [1] patch modify modified=1409169127 2014-09-02 20:38:00 [1] patch modify modified=1409170774 2014-09-02 20:38:00 [1] patch modify modified=1409173307 2014-09-02 20:38:00 [1] patch modify modified=1409174659 2014-09-02 20:38:00 [1] patch modify modified=1409176043 2014-09-02 20:38:00 [1] patch modify modified=1409177614 2014-09-02 20:38:00 [1] patch modify modified=1409178810 2014-09-02 20:38:00 [1] patch modify modified=1409180344 2014-09-02 20:38:00 [1] patch modify modified=1409181584 2014-09-02 20:38:00 [1] patch modify modified=1409187602 2014-09-02 20:38:00 [1] patch modify modified=1409187973 2014-09-02 20:38:00 [1] patch modify modified=1409192352 2014-09-02 20:38:00 [1] patch modify modified=1409192793 2014-09-02 20:38:00 [1] patch modify modified=1409194502 2014-09-02 20:38:00 [1] patch modify modified=1409195917 2014-09-02 20:38:00 [1] patch modify modified=1409199074 2014-09-02 20:38:00 [1] patch modify modified=1409200392 2014-09-02 20:38:00 [1] patch modify modified=1409202251 2014-09-02 20:38:00 [1] patch modify modified=1409203289 2014-09-02 20:38:00 [1] patch modify modified=1409204556 2014-09-02 20:38:00 [1] patch modify modified=1409205796 2014-09-02 20:38:00 [1] patch modify modified=1409209058 2014-09-02 20:38:00 [1] patch modify modified=1409211210 2014-09-02 20:38:00 [1] patch modify modified=1409212191 2014-09-02 20:38:00 [1] patch modify modified=1409237573 2014-09-02 20:38:00 [1] patch modify modified=1409238758 2014-09-02 20:38:00 [1] patch modify modified=1409240430 2014-09-02 20:38:00 [1] patch modify modified=1409244746 2014-09-02 20:38:00 [1] patch modify modified=1409246490 2014-09-02 20:38:00 [1] patch modify modified=1409249505 2014-09-02 20:38:00 [1] patch modify modified=1409251029 2014-09-02 20:38:00 [1] patch modify modified=1409253162 2014-09-02 20:38:00 [1] patch modify modified=1409254278 2014-09-02 20:38:00 [1] patch modify modified=1409255941 2014-09-02 20:38:00 [1] patch modify modified=1409257127 2014-09-02 20:38:00 [1] patch modify modified=1409260284 2014-09-02 20:38:00 [1] patch modify modified=1409261776 2014-09-02 20:38:00 [1] patch modify modified=1409263407 2014-09-02 20:38:00 [1] patch modify modified=1409264648 2014-09-02 20:38:00 [1] patch modify modified=1409267076 2014-09-02 20:38:00 [1] patch modify modified=1409268995 2014-09-02 20:38:00 [1] patch modify modified=1409271847 2014-09-02 20:38:00 [1] patch modify modified=1409273852 2014-09-02 20:38:00 [1] patch modify modified=1409275661 2014-09-02 20:38:00 [1] patch modify modified=1409277070 2014-09-02 20:38:00 [1] patch modify modified=1409278384 2014-09-02 20:38:00 [1] patch modify modified=1409279656 2014-09-02 20:38:00 [1] patch modify modified=1409281440 2014-09-02 20:38:00 [1] patch add end=1409282235 2014-09-02 20:38:00 [1] patch modify status=deleted 2014-09-02 20:38:00 [1] Merge result {"description":"[filtered]","due":"20140822T070000Z","end":"20140829T031715Z","entry":"20140822T010053Z","modified":"20140829T030400Z","priority":"M","project":"[filtered]","status":"deleted","tags":["filtered"],"uuid":"[filtered]"} 2014-09-02 20:38:16 ==== taskd 1.0.0 ==== 2014-09-02 20:38:16 Serving from /home/dev/taskddata 2014-09-02 20:38:16 Debug mode 2014-09-02 20:38:16 Using port 53589 2014-09-02 20:38:16 Queue size 10 requests 2014-09-02 20:38:16 Request size limit 1048576 bytes 2014-09-02 20:38:16 IP logging off 2014-09-02 20:38:16 client.allow /all/ 2014-09-02 20:38:16 CA /home/dev/taskddata/ca.cert.pem 2014-09-02 20:38:16 Certificate /home/dev/taskddata/server.cert.pem 2014-09-02 20:38:16 Private Key /home/dev/taskddata/server.key.pem 2014-09-02 20:38:16 CRL /home/dev/taskddata/server.crl.pem 2014-09-02 20:38:16 Server starting {code}

The next thing I looked at was the tx.data file. Here is a link to a filtered version: https://freecinc.com/tx.data.freecinc_533 In the tx.data file look for the string "Duplicated Annotation"

Here is a snippet from taskd.log. This shows the first entry in the taskd.log where the task with the duplicated annotations appears. Note the sync is from Mirakel, and the task appears to have two annotations and both of them get duplicated (look for 'filtered_annotation_1' and 'filtered_annotation_2').

From this I suspect the duplicated annotation is either happening in Mirakel, or is happening in taskd when syncing with Mirakel.

{code} 2014-08-13 16:50:17 [2521] 'sync' from 'FreeCinc/freecinc_**' using 'Mirakel 2.6.2' at :0 2014-08-13 16:50:17 [2521] Client key '[filtered]' 2 2014-08-13 16:50:17 [2521] Loaded 2258 records 2014-08-13 16:50:17 [2521] Branch point: [filtered] --> 2217 2014-08-13 16:50:17 [2521] Subset 39 tasks 2014-08-13 16:50:17 [2521] applying right 1407947726 >= 1407947209 2014-08-13 16:50:17 [2521] patch remove annotation_1407946987 2014-08-13 16:50:17 [2521] patch add annotation_1407947209=filtered_annotation_1 2014-08-13 16:50:17 [2521] patch modify modified=1407947209 2014-08-13 16:50:17 [2521] patch remove annotation_1407946987 2014-08-13 16:50:17 [2521] patch add annotation_1407947726=filtered_annotation_1 2014-08-13 16:50:17 [2521] patch modify modified=1407947726 2014-08-13 16:50:17 [2521] Merge result {"description":"[filtered]","entry":"20140813T162252Z","modified":"20140813T163526Z","project":"[filtered]","status":"pending","uuid":"[filtered]","annotations":[{"entry":"20140813T162649Z","description":"filtered_annotation_1"},{"entry":"20140813T163526Z","description":"filtered_annotation_1"}]} 2014-08-13 16:50:17 [2521] applying right 1407947727 >= 1407947209 2014-08-13 16:50:17 [2521] patch remove annotation_1407947098 2014-08-13 16:50:17 [2521] patch add annotation_1407947209=filtered_annotation_2 2014-08-13 16:50:17 [2521] patch modify modified=1407947209 2014-08-13 16:50:17 [2521] patch remove annotation_1407947098 2014-08-13 16:50:17 [2521] patch add annotation_1407947727=filtered_annotation_2 2014-08-13 16:50:17 [2521] patch modify modified=1407947727 2014-08-13 16:50:17 [2521] Merge result {"description":"[filtered]","entry":"20140813T162450Z","modified":"20140813T163527Z","project":"[filtered]","status":"pending","uuid":"[filtered]","annotations":[{"entry":"20140813T162649Z","description":"filtered_annotation_2"},{"entry":"20140813T163527Z","description":"filtered_annotation_2"}]} 2014-08-13 16:50:17 [2521] Stored 0 tasks, merged 2 tasks 2014-08-13 16:50:17 [2521] New sync key '[filtered]' 2014-08-13 16:50:17 [2521] Wrote 3 2014-08-13 16:50:17 [2521] Serviced in 0.101167s {code}

[taskwarrior]

Migrated metadata:

Created: 2014-09-03T05:29:00Z
Modified: 2016-11-26T16:14:34Z

[taskwarrior]

Jack on 2014-09-03T05:34:59Z says:

The owner of the account contacted me and offered some insight into the usage pattern:

"Jack, "I figured mine would be a fairly common use case, but there’s definitely something wonky going on. I’m using taskwarrior on my laptop (OSX), and Mirakel on two devices (nexus 4 and nexus 7). One of my clients (and I haven’t been able to figure out which, exactly, but probably Mirakel) is duplicating certain events, potentially up to hundreds of times per sync. This has very little effect on my experience as an “end user” but I can see as how it might be onerous for you (and I’d be happy to take steps to resolve the issue for you).

"I have each of my clients syncing on a regular basis, varying from every 15 minutes to once an hour. Last weekend I upgraded my OS to Mavericks and since then I’ve had to brew re-install p. much everything including taskwarrior and its dependencies. I think what may have brought this to a head today was that I ended up reinstalling taskwarrior before I reinstalled GnuTLS and possible the nettle dylibs (I don’t know what that is, fwiw) and there was some bad sync behavior which (I now gather) culminated in my account being manually disabled by you."

[taskwarrior]

David Gwilliam on 2014-09-03T17:13:34Z says:

As the owner of the tasks, let me add some context. I noticed while troubleshooting this issue yesterday that one task in particular had duplicated annotations while another did not. The non-duplicated annotation was a URL (complete with http://etc), while the duplicated annotations were notes to myself (about taskwarrior features I'd like, as it happens) that all included single quotes (not present in the URL). I wonder if this is relevant.

[taskwarrior]

Renato Alves on 2014-10-16T16:39:17Z says:

Hi Jack and David,

I've tried to reproduce this using only taskwarrior clients and the information you provided but have failed so far. So far I have not been able to crash taskd either. Will need further testing with larger datasets.

I'm also using Mirakel now and I already noticed some issues which probably need action from both sides (taskd and mirakel).

Jack, during these crashes did you notice anything strange in the system? Memory spikes, network issues, ...

Thanks

[taskwarrior]

Jack on 2014-10-16T17:03:52Z says:

Renato,

I don't recall anything strange in the system, but perhaps I just wasn't looking. TD-77 (just filed) is the only time I've seen memory spikes.

[taskwarrior]

Renato Alves on 2014-10-17T15:54:46Z says:

Jack, do you think this one could be yet another manifestation of TD-70 / TD-77 ?

[taskwarrior]

Jack on 2014-10-17T16:02:53Z says:

I wouldn't be surprised, since all known cases of taskd crashing seem to point to out-of-memory.

[taskwarrior]

Jack on 2014-10-17T16:04:45Z says:

There is still the question of how the duplicated annotations got there. Taskd? Taskwarrior? Mirakel? Not sure of the answer to that.

[taskwarrior]

Renato Alves on 2014-10-17T16:27:56Z says:

Given I've not been able to reproduce that behaviour, I'd bet on Mirakel. Though more data is needed if we (I) want to stop doing unfounded claims.

[taskwarrior]

David Gwilliam on 2014-10-17T16:58:32Z says:

Patient Zero here. Having done some testing on my own, I'm about 90% sure it's Mirakel. In particular, it seems to have issues with certain scheduled recurring tasks (which I think is a known issue) and annotations with some set of characters in them that I haven't been able to lock down.

[taskwarrior]

Renato Alves on 2014-10-17T17:31:15Z says:

Can you try adding some of these:

/\][}{)('";:=-+

If you are familiar with JSON and SQL try creating annotations that could potentially disrupt/corrupt the JSON-like format used during sync and the SQL database which Mirakel uses internally.

[taskwarrior]

Georg Semmler on 2014-10-21T16:18:48Z says:

(at)dhgwilliam Could you please add some more informations on the annotations issue in mirakel? About the issue with the recurring tasks: was it something like this https://mirakel.atlassian.net/browse/MIR-537?jql=status%20%3D%20Done ? Or something other? In this case please create a issue in mirakels jira and discribe what steps need to be done to reproduce this.

[taskwarrior]

Georg Semmler on 2014-10-25T18:48:29Z says:

Can you try adding some of these:

/\][}{)('";:=-+

If you are familiar with JSON and SQL try creating annotations that could potentially disrupt/corrupt the JSON-like format used during sync and the SQL database which Mirakel uses internally.

Tried to reproduce this with the string from above, but: All of those characters are encoded in the right way in the current version of mirakel.(Self compiled from gerrit). So this don't seem to cause this issue.

[lauft]

[!IMPORTANT] Taskserver is only compatible with Taskwarrior 2.x, and is no longer actively developed. See man task-sync for task synchronization with Taskwarrior 3