message history loads some sections of conversation multiple times

[mathuaerknedam]

Summary

Message history loads some sections of conversation multiple times.

Steps to reproduce

When I see it, it's consistent in that opening and closing the window or changing messages styles doesn't affect the bug. But I don't often notice it happening, so I don't know how to reproduce it. Since message history is loaded from the logs, maybe I can find a problem log and attach it to let others try reproducing this. Should that work?

Expected results

Each message in the chat transcript should be loaded once, up to the set number of lines.

Actual results

Some sections of conversation are repeated. In the conversation for the attached pic, the visible segment of conversation was repeated 4 times in 200 lines of history.

Regression

I think I've seen this for a long time, at least as long ago as when IRC was added, but it's always been hard to reproduce and I've often gone long periods without seeing it. It's also in 1.5hgr2871, but I don't believe it happens in 1.3.

[mathuaerknedam]

Logfile from #adium

[mathuaerknedam]

Pic of the chat window after loading attached log as message history

[mathuaerknedam]

##php log

[mathuaerknedam]

I've attached two log files, hopefully someone can use them to reproduce this. Looking at the pic, you can easily see how the messages from ThainEshKelch and holdenss are duplicated. In the ##php log the messages from "FSX, basically" to "I thought drupal" gets repeated a few times, and the attached pic shows how the message history doesn't even appear to be loading and/or displaying the logs in chronological order.

[mathuaerknedam]

I just verified that if I delete all other logs from #adium and open the chat window, the problem reoccurs. With a message history of 200 lines, the two messages are repeated twice at the very end (as seen int eh pic) and then occur only once before that. I tried changing the message history to 10 lines, and the problem still exists, so I don't think it's related to any particular message history line count.

[cbarrett]

I'm going to try to repro this with the attached logs. If I can reproduce, I'll take a stab at fixing it.

[evands]

Excellent, Colin.

[Zachary West <zacw@…>]

(In  37f86ef91f64) Code simplification; remove the old preferences, and don't use a static variable to count the lines. Refs #13362.

I can't imagine using a static variable like this wouldn't cause problems, especially with "save chats" enabled; we'd be messing with the same static variable like crazy. I'm betting this explains some weird context problems, so let's see if this helps #13362.

[Zachary West <zacw@…>]

(In  fa988de96a94) Don't deal with autorelease pools on the file level; deal with it in terms of chats. Refs #13362.

[Zachary West <zacw@…>]

(In  2a385da3eace) Don't use any instance variables to control parsing, use the parser's context info. Refs #13362.

[Zachary West <zacw@…>]

(In  24c471ce6c9e) Avoid draining items we're still using; fix for some reason putting "Value" in this context object. Refs #13362.

[Zachary West <zacw@…>]

(In  0eb39f6eb39c) Fix the context parser ignoring pages. Fixes #13362.

Every iteration was doing:

1. Move to location for reading.
2. Read
3. Move to location for next read.

So we were skipping reads like a mofo here. I believe this fixes any remaining context issues that un-instance-variableing didn't hit.

[zacw]

There's just a whole mess of bugs in the context stuff.

These fixed a set of bugs, too. but I am seeing the "multiple" problem too; it's not in the parser now, it's in dealing with LMX.

[Zachary West <zacw@…>]

(In  51687f71fc63) Fix a few more issues with context reading; if we're reading less than readSize, we need to decrement readSize too. Refs #13362.

[Zachary West <zacw@…>]

(In  fd43f6298e71) LMX.framework with my change at  http://bitbucket.org/zacwest/lmx-currentindexfix/changeset/9c19b3a4067c/, fixes currentIndex being lost, and repeating elements when processing multiple chunks. Fixes #13362.

[Zachary West <zacw@…>]

(In  37762b593bc4) LMX.framework with my change at  http://bitbucket.org/zacwest/lmx-x86_64-currentindexfix/changeset/c6c1e2dedf92/, fixes currentIndex being lost, and repeating elements when processing multiple chunks. Refs #13362.

/me shakes fist at sholt for applying his changes to the branch.

[David Munch]

This problem has resurfaced again in 1.4hg, and I assume it is caused by the commit that Evan made in #13499?

My console spits this out, don't know if it is related: 15/03/10 10.46.38, 15. mar, uge 11 Adium[142] Attempting to correct for old proxy listobject, keyed IRC.psychs-#growl.3

[evands]

This should be fixed (again) with sholt's change in [1721a9e92faf]:

changeset:   3157:1721a9e92faf
user:        Stephen Holt <sholt@adium.im>
date:        Sun Mar 14 00:47:48 2010 -0500
summary:     Use a ppc/i386/x86_64 binary for LMX. (merged my x86_64 fixes and zac's currentIndex fix in http://bitbucket.org/sholt/lmx/).  Build fix part The Second.

Please reopen if continued problems at tip. (David, that console logging is unrelated).

[mathuaerknedam]

I'm seeing this again, in 1.4b18. :(

[cbarrett]

I'm going to try one more time to reproduce this.

[David Munch]

For what it is worth (And sorry for logging on and off 20 times on IRC while testing :P): I have Adium set to remember the last 10 lines of history when I open a chat. If I close an IRC window, and reopen it, Adium of course remembers the last 10 lines and shows them. If I then close it again, and reopen, only 10 lines are shown. If I then close the chat, reopen it, and then quit Adium and relaunch it, I get two outcomes:

1. If the conversation of the last 'session' in the IRC room was a long one, Adium displays enough lines to fill the message window.
2. If the conversation of the last 'session' in the IRC room was short, Adium displays it twice - By short, I mean so few lines, that the conversation can be displayed twice in the message window without activating the scrollbar.

[evands]

1. If you're seeing this now, please email me a zip file of the chat transcripts folder for the contact it happens on. Last time, anyways, it had to do with very particular content of the transcript.

2. David, what is a 'long' conversation? Do you mean more than the 10 lines you've specified?

[David Munch]

Hi Evan,

No, I'm not seeing it right now unfortunately. I even tried testing the steps I posted above to no avail. It seems that I can only repeat it, if it has already happened with a piece of history. But I'll keep my eye out, as I usually see it somewhat regularly.

By a short conversation I mean a list of messages that only take up one line in the window each. So by long, I mean a list of messages where several of them needs more lines. I have a hunch, at least by experience the last time I witnessed this, that it has something to do with wether or not the last X lines of history can be displayed twice in the message view, without the appearence of the scrollbar. I've attached a screenshot to better visualize what I mean.

[David Munch]

A visual description of the bug, from my experience

[mathuaerknedam]

Using 1.4b18 I just verified repeating message history in seven chats. I left the windows open, launched 1.5hgd1c7e2b6b9d3 (tip as of right now), checked in the automatically opened chats, and could not find an instance of repeating message history. My problems did follow the sort of trend described by David.

As far as *I* can tell, this issue is resolved.

[David Munch]

I'd also say we close this one. I haven't seen it lately where it *should* have triggered, based on my descriptions above.

[Robby]

Okay! :)

[David Munch]

Okay, just got hit with it again on 1.4b19. Attached screenshots and .chatlog.

[David Munch]

Message window showing the bug in 1.4b19

[David Munch]

Transcriptviewer not showing the bug in 1.4b19

[David Munch]

1.4b19 chatlog that has the problem

[mathuaerknedam]

As far as I can tell, the  fix never made it into 1.4, only 1.5.

[David Munch]

Ah, didn't know that 1.5 had a fix. Closing in that case.

[mathuaerknedam]

Actually, the fix needs merged/transplanted/whatever into 1.4 too.

[evands]

The  changes mentioned above are related to the chat transcript viewer, not message history; they are unrelated to this bug.  85a3f8c6136e is the change which fixes this ticket originally, and it is on adium-1.4.

Does this *only* happen for IRC chats, David?

Could you please provide a debug log of it happening (next time, if you don't have debug logs being saved to disk that you can match up to this timeframe)?

[mathuaerknedam]

Weird coincidence. I saw problems after 85a3f8c6136e. Colin said he'd take a look and a week later committed 4dc4e5bceaa9 to 1.5. Five weeks later when I tried again, I could repoduce the problem in 1.4b18 (which included 85a3f8c6136e) but not 1.5 (which included Colin's change).

Sorry to confuse things.

[evands]

I think Colin was poking around that neighborhood and just got interested in fixing an unrelated flaw (that we were using complex, deprecated code in favor of the possibility of simpler, modern code) :)

[David Munch]

Replying to evands:

Does this *only* happen for IRC chats, David?

Could you please provide a debug log of it happening (next time, if you don't have debug logs being saved to disk that you can match up to this timeframe)?

I can not recall it happening on any non-IRC protocol, but that mean matter I haven't seen. The bug usually only pops up 1-2 times a month, and I have way more activity on my IRC rooms which are always open, compared to IM conversation..

I'll try to get the debug log.

[zacw]

Sounds like the majority of these bugs were fixed by the earlier changes. When we have a reproduction case let's fix the rest.

[mathuaerknedam]

I was able to reproduce this 12 days ago (on 1.4b18, but not 1.5hg) with several different contacts. The transcripts are on my work computer, and I probably won't be able to get debug logs until Monday.

[David Munch]

1.4b19 debuglog

[David Munch]

Screenshot along with debuglog, 1.4b19

[David Munch]

Screenshot + debug log in 1.4b19 of the problem on #adium. Let me know if you want the .chatlog.

[David Munch]

Still a problem in 1.4.

[sphynx]

Replying to evands:

The  changes mentioned above are related to the chat transcript viewer, not message history; they are unrelated to this bug.  85a3f8c6136e is the change which fixes this ticket originally, and it is on adium-1.4.

Yes, but  1721a9e92faf wasn't transplanted. I don't know how the LMX binaries differ exactly, but as is mentioned multiple times that this does occur on -1.4 but not on trunk, I think it is really fixed now in  327927ad486c.

[mathuaerknedam]

I can confirm that this does appear to fix the bug for me.