Multiple events fired for single event sent? (Win7 x64, nodejs, socket.io)

[Shannon Posniewski]

When using the latest and greatest nodejs (v0.6.12) and socket.io (v0.9.1-1), and the dead-simple example given here http://socket.io/#how-to-use, I get the connection event fired twice. This sends the "news" event back to the client twice. The server, however, appears to get the response ("my other event") four time. (I assume twice for each response from the client.)  It's as if the queue of events isn't being cleared on the server side, or some other odd thing along those lines. The client seems to be operating properly (i.e. no double-events, no extra events).

If I wait for a while, then the whole chain repeats itself, even though the client never reconnects via the "io.connect(...)" line. I verified this by putting in console.log()s and breakpoints on the client side. The debug log seems to indicate the websocket transport ended, so perhaps this is as expected as it auto-re-attaches. Still, though, it double-connects.

Considering this seems to happen with the vanilla example, I have to assume someone else has noticed it along the line. Are there problems with the Win64 side of things perhaps? I could fundamentally misunderstand how all this works, too.

Windows 7, x64

Chrome 18.0.1025.45

nodejs v0.6.12 (installed with Windows msi installer)

socket.io v0.9.1-1

Thanks for any help,

shannon

Here's the server log for a run:

C:\work\wb>node --debug wb.js

debugger listening on port 5858

   info  - socket.io started

C:\work\wb/index.html

   debug - served static content /socket.io.js

   debug - client authorized

   info  - handshake authorized 1300944561171091421

C:\work\wb/index.html

   debug - setting request GET /socket.io/1/websocket/1300944561171091421

   debug - set heartbeat interval for client 1300944561171091421

   debug - client authorized for

   debug - websocket writing 1::

1300944561171091421 [I printed the socket id out at the beginning of the "connection" handler]

   debug - websocket writing 5:::{"name":"news","args":[{"hello":"world"}]}

1300944561171091421

   debug - websocket writing 5:::{"name":"news","args":[{"hello":"world"}]}

{ my: 'data' }

{ my: 'data' }

{ my: 'data' }

{ my: 'data' }

   debug - emitting heartbeat for client 1300944561171091421

   debug - websocket writing 2::

   debug - set heartbeat timeout for client 1300944561171091421

   debug - got heartbeat packet

   debug - cleared heartbeat timeout for client 1300944561171091421

   debug - set heartbeat interval for client 1300944561171091421

   info  - transport end

   debug - set close timeout for client 1300944561171091421

   debug - cleared close timeout for client 1300944561171091421

   debug - cleared heartbeat interval for client 1300944561171091421

   debug - discarding transport

   debug - client authorized

   info  - handshake authorized 900933533848425194

   debug - setting request GET /socket.io/1/websocket/900933533848425194

   debug - set heartbeat interval for client 900933533848425194

   debug - client authorized for

   debug - websocket writing 1::

900933533848425194

   debug - websocket writing 5:::{"name":"news","args":[{"hello":"world"}]}

900933533848425194

   debug - websocket writing 5:::{"name":"news","args":[{"hello":"world"}]}

{ my: 'data' }

{ my: 'data' }

{ my: 'data' }

{ my: 'data' }

   debug - emitting heartbeat for client 900933533848425194

   debug - websocket writing 2::

   debug - set heartbeat timeout for client 900933533848425194

   debug - got heartbeat packet

   debug - cleared heartbeat timeout for client 900933533848425194

   debug - set heartbeat interval for client 900933533848425194

   info  - transport end

   debug - set close timeout for client 900933533848425194

   debug - cleared close timeout for client 900933533848425194

   debug - cleared heartbeat interval for client 900933533848425194

   debug - discarding transport

   debug - client authorized

   info  - handshake authorized 184719094279175023

   debug - setting request GET /socket.io/1/websocket/184719094279175023

   debug - set heartbeat interval for client 184719094279175023

   debug - client authorized for

   debug - websocket writing 1::

184719094279175023

   debug - websocket writing 5:::{"name":"news","args":[{"hello":"world"}]}

184719094279175023

   debug - websocket writing 5:::{"name":"news","args":[{"hello":"world"}]}

{ my: 'data' }

{ my: 'data' }

{ my: 'data' }

{ my: 'data' }

   debug - emitting heartbeat for client 184719094279175023

   debug - websocket writing 2::

   debug - set heartbeat timeout for client 184719094279175023

   debug - got heartbeat packet

   debug - cleared heartbeat timeout for client 184719094279175023

   debug - set heartbeat interval for client 184719094279175023

   info  - transport end

[Shannon Posniewski]

The debug log seems to indicate the websocket transport ended, so perhaps this is as expected as it auto-re-attaches.

This behavior is likely caused by the issue described here: https://groups.google.com/d/topic/socket_io/Vjr20Q1sOU4/discussion. So, disregard that part of the report.

However, the base problem where I get two callbacks for each event still exists.

shannon

[Shannon Posniewski]

Apologies for bumping my own post, but as there's been no response I'll assume no one is seeing this problem or everyone watching is using a different setup.

Can anyone confirm that the code here http://socket.io/#how-to-use works for them, getting only a single connection event, on Win64, nodejs (any recent version), and socket.io (any recent version)?

That would at least be a data point I can use to confirm or deny my sanity.

Huge appreciation for any reports,

shannon

[Anand George]

Please refer  http://groups.google.com/group/socket_io/browse_thread/thread/be387723b95a6181 . Should point you in the right direction.

Anand

[Shannon Posniewski]

Thanks for the pointer, Anand. And the confirmation that I'm not a ghost! :-)

That explains the restart, but not the double-eventing. After adding

    io.set('heartbeat interval', 20);
    io.set('heartbeat timeout', 60);

I still get the doubled events.

C:\work\wb>node --debug wb.js

debugger listening on port 5858

   info  - socket.io started

C:\work\wb/index.html

   debug - served static content /socket.io.js

   debug - client authorized

   info  - handshake authorized 12672025651492632160

C:\work\wb/index.html

   debug - setting request GET /socket.io/1/websocket/12672025651492632160

   debug - set heartbeat interval for client 12672025651492632160

   debug - client authorized for

   debug - websocket writing 1::

New connection => 12672025651492632160

   debug - websocket writing 5:::{"name":"news","args":[{"hello":"world"}]}

New connection => 12672025651492632160

   debug - websocket writing 5:::{"name":"news","args":[{"hello":"world"}]}

my other event => { my: 'data' }

my other event => { my: 'data' }

my other event => { my: 'data' }

my other event => { my: 'data' }

shannon

[Pavel Sakun]

Hi Shannon.

Could you narrow it down to some simple client and server and share the code? It would be much easier to find the cause.

--
Best regards.
Pavel.

[Veerabhadraiah A S]

I had the same problem. What i was doing was, I was calling the method which binds the listeners to the events multiple times, causing same method being attached to single event multiple times. So i resolved it by calling the method only once. Check for this..

On Fri, Aug 17, 2012 at 2:33 PM, Smile @rT <smile...@gmail.com> wrote:

The same problem! Shannon, how are you fixed this issue?

--
Thanks and Regards,
Veerabhadraiah A S,
Software Engineer,
Above Solutions India Pvt Ltd,
Indira Nagar,
Bangalore.