[zeromq-dev] Strange behaviour running Clone Server Reliability v6 example from ZGuide

[Pieter Hintjens]

Hi Matt,

It's my code and I'd look into this but have been flying around the
world for about three days non-stop, so won't.

Perhaps you can debug this and figure out what's going on.

Cheers
Pieter

On Wed, Feb 8, 2012 at 1:36 AM, Matt McClean <matt.mcclean at gmail.com> wrote:
> Hi there,
>
> Have tried to run the clone server example v6 from the Zguide and getting
> some weird behavior that I wanted to check. I am attempting to run the C
> example with two clone servers and two clients. I start the primary clone
> server and it gives the following output:
>
> MacBookPro:C matt$ clonesrv6 -p
> 12-02-08 11:28:22 I: primary master, waiting for backup (slave)
> 12-02-08 11:28:22 I: zloop: register SUB poller (0x7fb692403bb0, 0)
> 12-02-08 11:28:22 I: zloop: register timer delay=1000 times=0
> 12-02-08 11:28:22 I: zloop: register timer delay=1000 times=0
> 12-02-08 11:28:22 I: zloop: polling for 1000 msec
> 12-02-08 11:28:23 I: zloop: call timer handler
> 12-02-08 11:28:23 I: zloop: call timer handler
> 12-02-08 11:28:23 I: zloop: call timer handler
> 12-02-08 11:28:23 I: zloop: polling for 1000 msec
> 12-02-08 11:28:24 I: zloop: call timer handler
> 12-02-08 11:28:24 I: zloop: call timer handler
> 12-02-08 11:28:24 I: zloop: call timer handler
> 12-02-08 11:28:24 I: zloop: polling for 999 msec
>
> I then start the second clone server and it gives the following:
>
> MacBookPro:C matt$ clonesrv6 -b
> 12-02-08 11:29:01 I: backup slave, waiting for primary (master)
> 12-02-08 11:29:01 I: zloop: register SUB poller (0x7fbf5bc03b90, 0)
> 12-02-08 11:29:01 I: zloop: register timer delay=1000 times=0
> 12-02-08 11:29:01 I: zloop: register timer delay=1000 times=0
> 12-02-08 11:29:01 I: zloop: polling for 1000 msec
> 12-02-08 11:29:01 I: zloop: call SUB socket handler (0x7fbf5bd012a0, 0)
> 12-02-08 11:29:01 I: zloop: polling for 398 msec
> 12-02-08 11:29:02 I: zloop: call timer handler
> 12-02-08 11:29:02 I: zloop: call timer handler
> 12-02-08 11:29:02 I: zloop: call timer handler
> 12-02-08 11:29:02 I: zloop: polling for 1000 msec
> 12-02-08 11:29:02 I: zloop: call SUB socket handler (0x7fbf5bd012a0, 0)
> 12-02-08 11:29:02 I: connected to primary (master), ready as slave
> 12-02-08 11:29:02 I: zloop: register SUB poller (0x7fbf5bc04450, 0)
> 12-02-08 11:29:02 I: zloop: polling for 397 msec
> 12-02-08 11:29:02 I: zloop: call SUB socket handler (0x7fbf5bc04450, 0)
> 12-02-08 11:29:02 I: asking for snapshot from: tcp://localhost:5556
>
> Then the primary clone server starts spitting out a lot of output in the
> console with the following lines without any client connected:
>
> CLIENT REQUEST
> 12-02-08 11:29:26 I: zloop: polling for 670 msec
> 12-02-08 11:29:26 I: zloop: call ROUTER socket handler (0x7fb6924018a0, 0)
> CLIENT REQUEST
> 12-02-08 11:29:26 I: zloop: polling for 670 msec
> 12-02-08 11:29:26 I: zloop: call ROUTER socket handler (0x7fb6924018a0, 0)
> CLIENT REQUEST
> 12-02-08 11:29:26 I: zloop: polling for 670 msec
> 12-02-08 11:29:26 I: zloop: call ROUTER socket handler (0x7fb6924018a0, 0)
> CLIENT REQUEST
> 12-02-08 11:29:26 I: zloop: polling for 670 msec
> 12-02-08 11:29:26 I: zloop: call ROUTER socket handler (0x7fb6924018a0, 0)
> CLIENT REQUEST
> 12-02-08 11:29:26 I: zloop: polling for 670 msec
> 12-02-08 11:29:26 I: zloop: call ROUTER socket handler (0x7fb6924018a0, 0)
> CLIENT REQUEST
> 12-02-08 11:29:26 I: zloop: polling for 670 msec
> 12-02-08 11:29:26 I: zloop: call ROUTER socket handler (0x7fb6924018a0, 0)
> CLIENT REQUEST
> 12-02-08 11:29:26 I: zloop: polling for 670 msec
> 12-02-08 11:29:26 I: zloop: call ROUTER socket handler (0x7fb6924018a0, 0)
> CLIENT REQUEST
> 12-02-08 11:29:26 I: zloop: polling for 670 msec
> 12-02-08 11:29:26 I: zloop: ca
>
> I then try to connect client and it send messages OK but every so often they
> seem to detect that the primary clone server is down with the following
> output:
>
> MacBookPro:C matt$ clonecli6
> 12-02-08 11:31:41 I: adding server tcp://localhost:5556...
> 12-02-08 11:31:41 I: waiting for server at tcp://localhost:5556...
> 12-02-08 11:31:41 I: adding server tcp://localhost:5566...
> /client/8401
> /client/7984
> /client/3352
> /client/5539
> /client/3647
> 12-02-08 11:31:46 I: server at tcp://localhost:5556 didn't give hugz
> 12-02-08 11:31:46 I: waiting for server at tcp://localhost:5566...
> /client/9161
> /client/1416
> /client/2428
> /client/1566
> /client/1088
> 12-02-08 11:31:51 I: server at tcp://localhost:5566 didn't give hugz
> 12-02-08 11:31:51 I: waiting for server at tcp://localhost:5556...
> /client/5129
> /client/2960
>
> It seems strange behavior so wanted to check if this was normal for this
> example or not.
>
> Regards,
> Matt
>
> _______________________________________________
> zeromq-dev mailing list
> zeromq-dev at lists.zeromq.org
> http://lists.zeromq.org/mailman/listinfo/zeromq-dev
>