Summary | JS error during mailbox loading |
Queue | IMP |
Queue Version | Git master |
Type | Bug |
State | Resolved |
Priority | 1. Low |
Owners | slusarz (at) horde (dot) org |
Requester | jan (at) horde (dot) org |
Created | 03/31/2011 (5183 days ago) |
Due | |
Updated | 10/14/2011 (4986 days ago) |
Assigned | 04/19/2011 (5164 days ago) |
Resolved | 10/14/2011 (4986 days ago) |
Github Issue Link | |
Github Pull Request | |
Milestone | |
Patch | No |
State ⇒ Resolved
they may fix my issues. I haven't seen those errors happening since
then. I'll keep watching and close the ticket if they don't pop up
again within a few days.
deletion code, it seems that there was a rare opportunity for a race
condition in the previous code that may have caused this issue. So
maybe this newer code has fixed this issue.
can't reproduce it reliably, it's really hard to track down.
mark as stalled unless we (you) can find a way to reliably reproduce
and/or point to the area of the code that is allegedly broken.
viewPort response. IIUC the message count in there is wrong? Where
is it?
1. Isolate the first load request for the mailbox where you encounter
the error. This provides the initial state of the browser mailbox DB.
2. Find the delete Messages request that causes the error.
3. From these 2 you can figure out the index that originally existed,
but no longer exists, that is causing the error.
4. Given this sequence number/UID (also the cacheID values of the
mailboxes), you should take a look at the IMAP logs of the delete
request to see if anything looks strange. Also, pay attention to
reported number of messages in the mailbox - as I previously
mentioned, in all the cases I've seen that you have posted, it looks
like there is an off-by-one error somewhere in this message count.
The goal is to determine why the browser is dropping the DB record of
a message/UID that 1) still exists (according to IMAP and IMP server)
and 2) the browser previously reported to IMP server that it had
cached (the cache variable sent back in viewport requests).
viewPort response. IIUC the message count in there is wrong? Where is
it?
Priority ⇒ 1. Low
ticket (unless you are willing to track down) because I can't
reproduce, the symptoms don't make sense, and nobody else has reported
this issue.
Assigned to Michael Slusarz
State ⇒ Feedback
deleted - and the message count was 16. Sounds suspiciously like Bug
#9915.Check to see if the fix there helps here before I do any further debugging.
suspicious because it returned false, or is the expected?
cache has changed.
suspicious because it returned false, or is the expected?
view:INBOX.horde.bugs
cacheid:V1082203163|U48062|M107|9|1
slice:28:83
cache:{16}INBOX.horde.bugs40732,40755,40858,40988,41087,41117,41120,41277,41406,41428,41453,41606,41633,42593,42975,43214,43776,44267,44475,44872,44897,44913,44937,45033,45108,45128,45185,45188:45189,45219,45247,45278,45323,45370,45534,45570,45579:45580,45602,45612,45665,45808,45822,45871,45946,46156,46175,46219,46350,46498,46644,46838:46839,47188,47230,47300,47329,47332,47351,47366,47372,47385,47428,47447,47530,47585,47592,47614,47666,47679,47765,47825,47830,47833,47909,47931,47942,47945:47946,47949:47954,47991:47993,47996,48000,48002:48003,48005,48012,48017,48059,48061
checkcache:1
/*-secure-{"response":false}*/
New Attachment: horde.bugs.txt
of horde.bugs is the problem, here are the original viewPort results
of both.
New Attachment: bug9766[1].txt
deleteMessage:
view:INBOX.horde.cvs
cacheid:V991562206|U93796|M18|1|1
slice:1:71
cache:{15}INBOX.horde.cvs69762,69775,69778,70496,75382:75384,76595,82258:82259,84297,87437,88016,88926,90035,91220,91419,93795
uid:{15}INBOX.horde.cvs93795
/*-secure-{"response":{"deleted":{"mbox":"INBOX.horde.cvs","uids":"{15}INBOX.horde.cvs93795","remove":1},"ViewPort":{"updatecacheid":"V991562206|U93796|M16|1|1","view":"INBOX.horde.cvs"},"poll":{"INBOX.horde.cvs":0},"quota":{"m":"73% von
512MB","p":73}}}*/
viewPort:
view:INBOX.horde.bugs
cacheid:V1082203163|U48062|M107|9|1
slice:1:56
cache:{16}INBOX.horde.bugs40732,40755,40858,40988,41087,41117,41120,41277,41406,41428,41453,41606,41633,42593,42975,43214,43776,44267,44475,44872,44897,44913,44937,45033,45108,45128,45185,45188:45189,45219,45247,45278,45323,45370,45534,45570,45579:45580,45602,45612,45665,45808,45822,45871,45946,46156,46175,46219,46350,46498,46644,46838:46839,47188,47230,47300,47329,47332,47351,47366,47372,47385,47428,47447,47530,47585,47592,47614,47666,47679,47765,47825,47830,47833,47909,47931,47942,47945:47946,47949:47954,47991:47993,47996,48000,48002:48003,48005,48012,48017,48059,48061
checkcache:1
/*-secure-{"response":{"ViewPort":{"cacheid":"V1082203163|U48066|M111|9|1","data":{"48063":{"imapuid":48063,"view":"INBOX.horde.bugs","flag":["unseen","personal"],"draft":1,"size":"4 KB","date":"20:48:15","from":"bugs@horde.org","subject":"[Tickets
#9905] Re: save contacts"},"48062":{"imapuid":48062,"view":"INBOX.horde.bugs","flag":["unseen","personal"],"draft":1,"size":"4 KB","date":"20:46:03","from":"bugs@horde.org","subject":"[Tickets#9905] Re: save contacts"},"48064":{"imapuid":48064,"view":"INBOX.horde.bugs","flag":["unseen","personal"],"draft":1,"size":"4 KB","date":"19:30:42","from":"bugs@horde.org","subject":"[Tickets#9814] Re: New tasklist not showing up"},"48065":{"imapuid":48065,"view":"INBOX.horde.bugs","flag":["unseen","personal"],"draft":1,"size":"4 KB","date":"19:30:09","from":"bugs@horde.org","subject":"[Tickets#9814] Re: New tasklist not showing up"}},"metadata":{"readonly":0,"unseen":62,"thread":{"48063":"3","48062":"4","48064":"3","48065":"4","48059":"","48061":"3","48017":"4","48012":"","48003":"","48000":"","47996":"","47993":"","47942":"","48005":"3","48002":"2","47992":"2","47991":"2","47954":"2","47953":"2","47952":"2","47951":"2","47950":"2","47949":"2","47946":"2","47945":"2","47931":"4","47909":"","47833":"","47830":"","47825":"","47666":"","47679":"","47614":"","47592":"3","47585":"4","47530":"","47372":"","47351":"3","47332":"4","47329":"","47447":"3","47385":"2","47366":"2","47300":"","47230":"","47188":"","46644":"","46498":"","46350":"","46219":"","46175":"","46156":"","45946":"","45871":"","45822":"","45808":""}},"rowlist":{"48063":1,"48062":2,"48064":3,"48065":4,"48059":5,"48061":6,"48017":7,"48012":8,"48003":9,"48000":10,"47996":11,"47993":12,"47942":13,"48005":14,"48002":15,"47992":16,"47991":17,"47954":18,"47953":19,"47952":20,"47951":21,"47950":22,"47949":23,"47946":24,"47945":25,"47931":26,"47909":27,"47833":28,"47830":29,"47825":30,"47666":31,"47679":32,"47614":33,"47592":34,"47585":35,"47530":36,"47372":37,"47351":38,"47332":39,"47329":40,"47447":41,"47385":42,"47366":43,"47300":44,"47230":45,"47188":46,"46644":47,"46498":48,"46350":49,"46219":50,"46175":51,"46156":52,"45946":53,"45871":54,"45822":55,"45808":56},"totalrows":111,"view":"INBOX.horde.bugs","update":1},"poll":{"INBOX.horde.bugs":62},"quota":{"m":"73% von512MB","p":73}}}*/
have access to the javascript request logs, but it would be useful to
know what the initial load of INBOX looked like - namely, if the
browser ever sent the data to the browser, or if the browser somehow
lost the data entry along the way.
request/response). If there were several requests in a row after
your last human-triggered action, provide the details of all those
requests (e.g. you initiated a deleteMessage, which was immediately
followed by a ViewPort request).
view:INBOX.horde.cvs
cacheid:V991562206|U93757|M18|1|1
slice:1:71
cache:{15}INBOX.horde.cvs69762,69775,69778,70496,75382:75384,76595,82258:82259,84297,87437,88016,88926,90035,91220,91419,93756
uid:{15}INBOX.horde.cvs93756
/*-secure-{"response":{"deleted":{"mbox":"INBOX.horde.cvs","uids":"{15}INBOX.horde.cvs93756","remove":1},"ViewPort":{"updatecacheid":"V991562206|U93757|M16|1|1","view":"INBOX.horde.cvs"},"poll":{"INBOX.horde.cvs":0},"quota":{"m":"77% von
512MB","p":76}}}*/
viewPort:
view:INBOX
cacheid:V968256253|U229698|M126|9|1
slice:1:56
cache:{5}INBOX207531,207671,208041,208282:208283,208285:208286,208299:208300,208303:208304,208306,208310,208319,208324,208328,208367,208372,212054,213533,213681,213960:213961,215418,215546,216366,216809,216874,218813,218999,219399,219403,222960,225664,225701,225918,226409,226480,226868,227085,227459:227460,228044,228139:228140,228142:228143,228314,228317,228441,229451,229490,229535,229672,229688,229692
checkcache:1
/*-secure-{"response":{"ViewPort":{"cacheid":"V968256253|U229702|M130|9|1","data":{"229699":{"imapuid":229699,"view":"INBOX","flag":["unseen","personal"],"draft":1,"size":"4 KB","date":"15.04.2011","from":"Ezra Platt","subject":"Ingrid, Good Afternoon Vernona"},"229701":{"imapuid":229701,"view":"INBOX","flag":["unseen","personal"],"draft":1,"size":"3 KB","date":"20:04:00","from":"nobody","subject":"PHP error_log message"},"229700":{"imapuid":229700,"view":"INBOX","flag":["unseen","personal"],"draft":1,"size":"3 KB","date":"20:03:16","from":"nobody","subject":"PHP error_log message"},"229698":{"imapuid":229698,"view":"INBOX","flag":["unseen","personal"],"draft":1,"size":"3 KB","date":"19:55:22","from":"munin@wg.de","subject":"Munin notification"}},"metadata":{"readonly":0,"unseen":13,"thread":{"229699":"","229701":"3","229700":"4","229698":"","229688":"","229672":"","229692":"","229535":"","229490":"","229451":"","228441":"","228317":"3","228314":"2","228139":"4","228140":"","228044":"","228142":"","228143":"","227460":"","227459":"","227085":"3","226868":"","226480":"3","226409":"","225918":"","225701":"","225664":"","222960":"","219403":"3","219399":"","218999":"","218813":"","216874":"","216809":"","216366":"","215546":"","215418":"","213961":"","213960":"","213681":"","213533":"","212054":"","208319":"","208372":"3","208367":"2","208328":"2","208324":"2","208310":"2","208306":"103","208304":"13","208303":"2","208300":"13","208299":"2","208286":"2","208285":"103","208283":"13"}},"rowlist":{"229699":1,"229701":2,"229700":3,"229698":4,"229688":5,"229672":6,"229692":7,"229535":8,"229490":9,"229451":10,"228441":11,"228317":12,"228314":13,"228139":14,"228140":15,"228044":16,"228142":17,"228143":18,"227460":19,"227459":20,"227085":21,"226868":22,"226480":23,"226409":24,"225918":25,"225701":26,"225664":27,"222960":28,"219403":29,"219399":30,"218999":31,"218813":32,"216874":33,"216809":34,"216366":35,"215546":36,"215418":37,"213961":38,"213960":39,"213681":40,"213533":41,"212054":42,"208319":43,"208372":44,"208367":45,"208328":46,"208324":47,"208310":48,"208306":49,"208304":50,"208303":51,"208300":52,"208299":53,"208286":54,"208285":55,"208283":56},"totalrows":130,"view":"INBOX","update":1},"poll":{"INBOX":13},"quota":{"m":"77% von
512MB","p":76}}}*/
New Attachment: bug9766.txt
down? Catching this error in ViewPort.update() gives another error
instead:
/headhorde/imp/js/dimpbase.js:696 Uncaught TypeError: Cannot call
method 'size' of undefined
DimpBase.viewport._getBuffer().debug()
Put the resulting JSON into an attachment.
Also, it is useful to indicate the last action you were doing (JSON
request/response). If there were several requests in a row after your
last human-triggered action, provide the details of all those requests
(e.g. you initiated a deleteMessage, which was immediately followed by
a ViewPort request).
Priority ⇒ 2. Medium
down? Catching this error in ViewPort.update() gives another error
instead:
/headhorde/imp/js/dimpbase.js:696 Uncaught TypeError: Cannot call
method 'size' of undefined
is that the cache ID is reporting 154 messages in the mailbox:
"cacheid":"V991562227|U46525|M154|9|1"
But later, the total rows is indicated as 155:
"totalrows":155
Maybe a message was delivered between beginning and ending of
processing? But even then, this theoretically shouldn't break things
- there was just need to be another update on the next server access.
onException #<Hash:{'message': 'Cannot set property \'VP_rownum\' of
undefined', 'stack': 'TypeError: Cannot set property \'VP_rownum\' of
undefined\n at klass.<anonymous>
(http://neo.wg.de/headhorde/imp/js/viewport.js:1501:44)\n at
http://neo.wg.de/headhorde/js/prototype.js:825:18\n at klass._each
(http://neo.wg.de/headhorde/js/prototype.js:1237:7)\n at klass.each
(http://neo.wg.de/headhorde/js/prototype.js:824:12)\n at
klass.update (http://neo.wg.de/headhorde/imp/js/viewport.js:1500:11)\n
at klass._ajaxResponse
(http://neo.wg.de/headhorde/imp/js/viewport.js:863:16)\n at
klass.parseJSONResponse
(http://neo.wg.de/headhorde/imp/js/viewport.js:844:18)\n at
Object.onDoActionComplete
(http://neo.wg.de/headhorde/imp/js/dimpbase.js:3481:27)\n at
Object.doActionComplete
(http://neo.wg.de/headhorde/imp/js/dimpcore.js:210:18)\n at
http://neo.wg.de/headhorde/imp/js/dimpbase.js:547:26', 'type':
'non_object_property_store', 'arguments': ['VP_rownum', undefined],
'name': 'TypeError'}>
And these are two requests right before that:
deleteMessage
view:INBOX.horde.dev
cacheid:V991562227|U46525|M156|9|1
slice:1:66
cache:{15}INBOX.horde.dev40218,40758,40801,41027,41064,41068:41069,41173,41288,41587,41774,42359,42481,42495,42589:42592,42598,42607,42613,42615:42616,42618:42619,42631,42634,42793,42802,43020,43747,44245:44246,44260,44262,44523:44526,44543:44544,44546,44549,44557:44561,44584,44588:44589,44591:44592,44609,44734,44745,45384,45387,45390,45402,45416,45966,45972,45980,45985,46524
uid:{15}INBOX.horde.dev46524
/*-secure-{"response":{"deleted":{"mbox":"INBOX.horde.dev","uids":"{15}INBOX.horde.dev46524","remove":1},"ViewPort":{"cacheid":"V991562227|U46525|M154|9|1","data":{"39879":{"imapuid":39879,"view":"INBOX.horde.dev","flag":["\\seen"],"draft":1,"size":"6 KB","date":"15.10.2008","from":"duck","subject":"Re: [core] horde hosting
service","listmsg":1}},"metadata":{"readonly":0,"unseen":0,"thread":{"45985":"003","45980":"03","45972":"3","45966":"","45402":"03","45416":"013","45390":"02","45387":"3","45384":"","44734":"","44561":"03","44558":"3","44546":"13","44544":"2","44543":"","44559":"03","44560":"0103","44557":"013","44549":"02","44745":"0100003","44592":"010003","44591":"01003","44609":"0100103","44589":"010013","44588":"01002","44584":"0103","44526":"013","44525":"02","44524":"3","44523":"","44262":"003","44260":"03","44246":"3","44245":"","43747":"","43020":"","42619":"00000003","42618":"0000003","42616":"000003","42615":"00003","42613":"0003","42607":"003","42598":"03","42495":"3","42481":"","42802":"000003","42793":"00003","42634":"0003","42631":"003","42592":"03","42590":"013","42591":"02","42589":"3","42359":"","41774":"","41587":"","41288":"","41173":"","41069":"03","41068":"3","41064":"","41027":"","40801":"","40758":"","40218":"","39879":"03"}},"rowlist":{"45985":1,"45980":2,"45972":3,"45966":4,
"45402":5,"45416":6,"45390":7,"45387":8,"45384":9,"44734":10,"44561":11,"44558":12,"44546":13,"44544":14,"44543":15,"44559":16,"44560":17,"44557":18,"44549":19,"44745":20,"44592":21,"44591":22,"44609":23,"44589":24,"44588":25,"44584":26,"44526":27,"44525":28,"44524":29,"44523":30,"44262":31,"44260":32,"44246":33,"44245":34,"43747":35,"43020":36,"42619":37,"42618":38,"42616":39,"42615":40,"42613":41,"42607":42,"42598":43,"42495":44,"42481":45,"42802":46,"42793":47,"42634":48,"42631":49,"42592":50,"42590":51,"42591":52,"42589":53,"42359":54,"41774":55,"41587":56,"41288":57,"41173":58,"41069":59,"41068":60,"41064":61,"41027":62,"40801":63,"40758":64,"40218":65,"39879":66},"totalrows":155,"view":"INBOX.horde.dev","update":1,"disappear":[46524]},"poll":{"INBOX.horde.dev":0}}}*/
viewPort
view:INBOX.horde.cvs
cacheid:V991562206|U93470|M16|1|1
slice:1:87
cache:{15}INBOX.horde.cvs69762,69775,69778,70496,75382:75384,76595,82258:82259,84297,87437,88016,88926,90035,91220,91419,93381
checkcache:1
/*-secure-{"response":{"ViewPort":{"cacheid":"V991562206|U93472|M20|1|1","data":{"93471":{"imapuid":93471,"view":"INBOX.horde.cvs","flag":["unseen"],"draft":1,"size":"5 KB","date":"23:22:27","from":"Michael M Slusarz","subject":"[commits] Horde branch master updated. c2a2ec543eeb5514c4883682a563d91c6f267668"},"93470":{"imapuid":93470,"view":"INBOX.horde.cvs","flag":["unseen"],"draft":1,"size":"8 KB","date":"23:18:52","from":"Michael M Slusarz","subject":"[commits] Horde branch master updated.
a9fe4dfb0a67fb51cd82c06a39808d7b3f8d0d0a"}},"metadata":{"readonly":0,"unseen":2},"rowlist":{"93471":1,"93470":2,"93381":3,"91419":4,"91220":5,"90035":6,"88926":7,"88016":8,"87437":9,"84297":10,"82259":11,"82258":12,"76595":13,"75384":14,"75383":15,"75382":16,"70496":17,"69778":18,"69775":19,"69762":20},"totalrows":20,"view":"INBOX.horde.cvs","update":1}}}*/
AJAX return listed an IMAP UID in the rowlist, but had no
corresponding data entry.
But I have no idea how this happened. Could be a session cache issue,
could be a browser cache issue, could be broken data for a message
that caused that message data to be null, etc. Without a reliable way
to reproduce, not sure if we can do much with this ticket.
Priority ⇒ 1. Low
State ⇒ Unconfirmed
Patch ⇒ No
Milestone ⇒
Summary ⇒ JS error during mailbox loading
Type ⇒ Bug
Queue ⇒ IMP
problems. I'm not sure if the error in the js log is from that
problem, or from navigating to another mailbox after that. Anyway,
here it is:
33onException #<Hash:{'message': 'Cannot set property \'VP_rownum\' of
undefined', 'stack': 'TypeError: Cannot set property \'VP_rownum\' of
undefined\n at klass.<anonymous>
(http://neo.wg.de/headhorde/imp/js/viewport.js:1501:44)\n at
http://neo.wg.de/headhorde/js/prototype.js:825:18\n at klass._each
(http://neo.wg.de/headhorde/js/prototype.js:1237:7)\n at klass.each
(http://neo.wg.de/headhorde/js/prototype.js:824:12)\n at
klass.update (http://neo.wg.de/headhorde/imp/js/viewport.js:1500:11)\n
at klass._ajaxResponse
(http://neo.wg.de/headhorde/imp/js/viewport.js:863:16)\n at
klass.parseJSONResponse
(http://neo.wg.de/headhorde/imp/js/viewport.js:844:18)\n at
Object.onDoActionComplete
(http://neo.wg.de/headhorde/imp/js/dimpbase.js:3481:27)\n at
Object.doActionComplete
(http://neo.wg.de/headhorde/imp/js/dimpcore.js:210:18)\n at
http://neo.wg.de/headhorde/imp/js/dimpbase.js:547:26', 'type':
'non_object_property_store', 'arguments': ['VP_rownum', undefined],
'name': 'TypeError'}>