Callbacks dropped on XP

[GoogleCodeExporter]

piisnear3.1415927 reported missing callback notifications on XP. I modified
test3() from the outfox demo page to mimick the problem scenario:

function test3(button) {
    var node = document.getElementById('test3-text');
    enableButtons(false);
    var token = outfox.addObserver(function(tts, cmd) {
    console.log(cmd);
    });
    outfox.play(window.location.href+'bell.mp3', 0, 'reward');
    outfox.say(node.innerHTML, 0, 'question');
    outfox.play(window.location.href+'bell.mp3', 0, 'prompt');
    outfox.play(window.location.href+'bell.mp3', 0, 'reward');
    outfox.say(node.innerHTML, 0, 'question');
    outfox.play(window.location.href+'bell.mp3', 0, 'prompt');
}

I cannot reproduce the problem. I get all of the following callbacks logged
in Firebug:

Object action=started-play name=reward channel=0
Object action=finished-play name=reward channel=0
Object action=started-say name=question channel=0
Object action=started-word length=5 name=question channel=0
Object action=started-word length=3 location=6 channel=0
Object action=started-word length=6 location=10 channel=0
Object action=started-word length=2 location=17 channel=0
Object action=started-word length=5 location=20 channel=0
Object action=started-word length=6 location=26 channel=0
Object action=started-word length=3 location=33 channel=0
Object action=started-word length=4 location=37 channel=0
Object action=started-word length=1 location=42 channel=0
Object action=started-word length=5 location=44 channel=0
Object action=finished-say name=question channel=0
Object action=started-play name=prompt channel=0
Object action=finished-play name=prompt channel=0
Object action=started-play name=reward channel=0
Object action=finished-play name=reward channel=0
Object action=started-say name=question channel=0
Object action=started-word length=5 name=question channel=0
Object action=started-word length=3 location=6 channel=0
Object action=started-word length=6 location=10 channel=0
Object action=started-word length=2 location=17 channel=0
Object action=started-word length=5 location=20 channel=0
Object action=started-word length=6 location=26 channel=0
Object action=started-word length=3 location=33 channel=0
Object action=started-word length=4 location=37 channel=0
Object action=started-word length=1 location=42 channel=0
Object action=started-word length=5 location=44 channel=0
Object action=finished-say name=question channel=0
Object action=started-play name=prompt channel=0
Object action=finished-play name=prompt channel=0

Need verification that this test works / fails on the bad machine. Also
need info about whether it fits the scenario or not.

Original issue reported on code.google.com by c...@unc.edu on 5 Aug 2008 at 1:29

[GoogleCodeExporter]

I did some logging today using the offending laptop. Adding some logging down in
onDataAvailable in server.js shows it never gets called with a partial message, 
and
it never gets called with more than one message so neither of those hard cases 
is
involved. When the bug occurs it is called and fetches a message that is 
identical to
one it fetched earlier. It looks to me like the message duplication is happening
below it. The server did not, apparently, send duplicate messages. It appears 
to be
sending all the right stuff. I tried hacking in sequence numbers to the 
messages but
broke things in the attempt.

So it looks to me like we get the callback to the onDataAvailable and when we 
fetch
the message it is a duplicate. Others have apparently be lost.

Original comment by piisnear...@gmail.com on 5 Aug 2008 at 10:47

[GoogleCodeExporter]

I can see something happening on the server side at the offending command. I 
added
the following to server.py
    def initiate_send (self):
        print 'is: start'
        obs = self.ac_out_buffer_size
        # try to refill the buffer
        if (len (self.ac_out_buffer) < obs):
            print 'is: refill'
            self.refill_buffer()

        if self.ac_out_buffer and self.connected:
            # try to send the buffer
            try:
                num_sent = self.send (self.ac_out_buffer[:obs])
                print 'is: ', num_sent, repr(self.ac_out_buffer[:obs])
                if num_sent:
                    self.ac_out_buffer = self.ac_out_buffer[num_sent:]

            except socket.error, why:
                print 'is: exception', why
                self.handle_error()
                return
        print 'is: done'

the above is simply a copy of the corresponding function from asynchat.py with 
added
prints. The interesting part of the resulting output is:
is: start

is: refill

is:  96 '{"seqno": 17, "cmd": {"action": "finished-play", "name": "reward",
"channel": 0}, "page_id": 4}\x03'

is: done

got {u'url':
u'http://gb-cs.cs.unc.edu/work/learn/try1/Sounds/Misc/Name%20that%20animal_Quest
ion.mp3',
u'action': u'play', u'channel': 0} 4

got {u'url': 
u'http://gb-cs.cs.unc.edu/work/learn/try1/Sounds/Animals/Rooster.mp3',
u'action': u'play', u'name': u'prompt', u'channel': 0} 4

is:  96 ''

is: done

Note that next to last line... It is the print after the self.send(...). First 
it is
amazing that we got to that print without seeing the is:start line, it is like 
we
have re-entered the function. Second, it says it wrote 96 bytes but the string 
it
wrote was empty...

The bottom line, as far as I can tell, is that asynchat is behaving very 
strangely.
In fact in ways I wouldn't have imagined possible. 

Original comment by piisnear...@gmail.com on 6 Aug 2008 at 3:28

[GoogleCodeExporter]

Original comment by piisnear...@gmail.com on 6 Aug 2008 at 3:29

• Added labels: Milestone-0.1.1

[GoogleCodeExporter]

I just noticed another detail. I should have included a few more lines of 
logging.
Notice below that we do indeed re-enter the function. We see is:start, 
is:refill a
couple of got logs that are coming from outfox.py, then another is:start, 
s:refill,
the send, done, then the first one tries the send screwing up in the process, 
the the
first one terminates.

chan onPlayerComplete

chan msg= {'action': 'finished-play', 'name': u'reward', 'channel': 0}

sending {"seqno": 17, "cmd": {"action": "finished-play", "name": "reward", 
"channel":
0}, "page_id": 4}

is: start

is: refill

got {u'url':
u'http://gb-cs.cs.unc.edu/work/learn/try1/Sounds/Misc/Name%20that%20animal_Quest
ion_3.mp3',
u'action': u'play', u'channel': 0} 4

got {u'url': u'http://gb-cs.cs.unc.edu/work/learn/try1/Sounds/Animals/Cow.mp3',
u'action': u'play', u'name': u'prompt', u'channel': 0} 4

is: start

is: refill

is:  96 '{"seqno": 17, "cmd": {"action": "finished-play", "name": "reward",
"channel": 0}, "page_id": 4}\x03'

is: done

got {u'url':
u'http://gb-cs.cs.unc.edu/work/learn/try1/Sounds/Misc/Name%20that%20animal_Quest
ion.mp3',
u'action': u'play', u'channel': 0} 4

got {u'url': 
u'http://gb-cs.cs.unc.edu/work/learn/try1/Sounds/Animals/Rooster.mp3',
u'action': u'play', u'name': u'prompt', u'channel': 0} 4

is:  96 ''

is: done

Original comment by piisnear...@gmail.com on 6 Aug 2008 at 3:49

[GoogleCodeExporter]

Committed a possible fix in rev 74. Merged asyncore loop and pygame look for 
win32
and nix. Need a test on the offending machine. Close bug as fixed if it works.

Original comment by c...@unc.edu on 7 Aug 2008 at 12:36

[GoogleCodeExporter]

piisnear reports as fixed on the original offending laptop. Closing bug. Reopen 
if
the problem resurfaces.

Original comment by c...@unc.edu on 10 Aug 2008 at 7:43

• Changed state: Fixed