zbroker icon indicating copy to clipboard operation
zbroker copied to clipboard

problem: server state flapping

Open rpedde opened this issue 11 years ago • 1 comments
trafficstars

Servers appear and vanish causing reader or writer messages to be missed by the other side. At least I'm assuming that's what is happening. I certainly don't see the writer message on the read side.

I also wonder about these messages:

I: 14-08-21 10:48:39 ZPIPES server vanished from I: 14-08-21 10:48:39 ZPIPES server vanished from

Here is an example:

Error in test "/home/rpedde/working/work/python-zbroker/scripts/simple_writer.yml"

Host "writer" (airbook.local)

Post started at: 14-08-21 10:48:38 Running tasks: 1

Test script

sleep 1
timeout 5000
open pipe1 write
write pipe1 abc
close pipe1 write

Script Log

14-08-21 10:48:39 Set prefix to 1
14-08-21 10:48:39 Set broker to 1-0
14-08-21 10:48:39 Sleeping for 1 seconds
14-08-21 10:48:40 Set timeout to 5000
14-08-21 10:48:40 Opening descriptor "1-0|>1-pipe1"
14-08-21 10:48:40 Opened pipe "pipe1" for write
14-08-21 10:48:40 Writing "abc" to pipe "pipe1"
14-08-21 10:48:40 Wrote to pipe "pipe1"
14-08-21 10:48:40 Closing write pipe "pipe1"
14-08-21 10:48:40 Closed pipe "pipe1"
14-08-21 10:48:40 Test passed

Broker Log

GNU gdb (GDB) 7.4.1-debian
Copyright (C) 2012 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
Reading symbols from /opt/bundler/zvm2-zpipes/zvm2-zpipes-00009/bin/zbroker...done.
(gdb) (gdb) (gdb) Starting program: /opt/bundler/zvm2-zpipes/zvm2-zpipes-00009/bin/zbroker /tmp/tmplmLYkB/zbroker.cfg
warning: no loadable sections found in added symbol-file system-supplied DSO at 0x7ffff7ffa000
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
zbroker service/0.0.2
Copyright (c) 2014 the Contributors
This Software is provided under the MPLv2 License on an "as is" basis,
without warranty of any kind, either expressed, implied, or statutory.

I: 14-08-21 10:48:38 starting zpipes broker using config in '/tmp/tmplmLYkB/zbroker.cfg'
N: 14-08-21 10:48:38 starting zpipes service
I: 14-08-21 10:48:38 using TCP gossip discovery service
I: 14-08-21 10:48:38 gossip service connect to tcp://airbook.local:5672
[New Thread 0x7ffff65af700 (LWP 1607)]
[New Thread 0x7ffff5dae700 (LWP 1612)]
[New Thread 0x7ffff55ad700 (LWP 1613)]
[New Thread 0x7ffff4dac700 (LWP 1614)]
[New Thread 0x7ffff45ab700 (LWP 1615)]
I: 14-08-21 10:48:38 Zyre starting gossip discovery, endpoint=tcp://airbook.internal.pedde.com:49153
I: 14-08-21 10:48:38 joining cluster as AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 7842BE
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:38 ZPIPES server vanished from 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 44D6FF
I: 14-08-21 10:48:39 ZPIPES server vanished from 
I: 14-08-21 10:48:39 ZPIPES server vanished from 
D: 14-08-21 10:48:40    246:                                : start:
D: 14-08-21 10:48:40    246:                                :     OUTPUT
D: 14-08-21 10:48:40    246:                                :         $ lookup or create pipe
D: 14-08-21 10:48:40    246:1-pipe1                         :         $ open pipe writer
I: 14-08-21 10:48:40 1-pipe1: attach local writer
I: 14-08-21 10:48:40 1-pipe1: broadcast we are now writer
I: 14-08-21 10:48:40 open local writer
D: 14-08-21 10:48:40    246:1-pipe1                         :         > before writing
D: 14-08-21 10:48:40    246:1-pipe1                         : before writing:
D: 14-08-21 10:48:40    246:1-pipe1                         :     ok
D: 14-08-21 10:48:40    246:1-pipe1                         :         $ send OUTPUT_OK
D: 14-08-21 10:48:40    246:1-pipe1                         :         > writing
I: 14-08-21 10:48:40 peer=44D6FF command=HAVE READER pipe=1-pipe1 unicast=0
I: 14-08-21 10:48:40 1-pipe1: attach remote reader
I: 14-08-21 10:48:40 1-pipe1: tell peer we are now writer
D: 14-08-21 10:48:40    246:1-pipe1                         : writing:
D: 14-08-21 10:48:40    246:1-pipe1                         :     have reader
D: 14-08-21 10:48:40    246:1-pipe1                         :         > writing
D: 14-08-21 10:48:40    246:1-pipe1                         : writing:
D: 14-08-21 10:48:40    246:1-pipe1                         :     WRITE
D: 14-08-21 10:48:40    246:1-pipe1                         :         $ process write request
D: 14-08-21 10:48:40    246:1-pipe1                         :         > processing write
D: 14-08-21 10:48:40    246:1-pipe1                         : processing write:
D: 14-08-21 10:48:40    246:1-pipe1                         :     have reader
D: 14-08-21 10:48:40    246:1-pipe1                         :         $ pass data to reader
I: 14-08-21 10:48:40 write 3 bytes
D: 14-08-21 10:48:40    246:1-pipe1                         :         $ send WRITE_OK
D: 14-08-21 10:48:40    246:1-pipe1                         :         > writing
D: 14-08-21 10:48:40    246:1-pipe1                         : writing:
D: 14-08-21 10:48:40    246:1-pipe1                         :     CLOSE
D: 14-08-21 10:48:40    246:1-pipe1                         :         $ close pipe writer
I: 14-08-21 10:48:40 1-pipe1: tell peer we stopped being writer
I: 14-08-21 10:48:40 close local writer
D: 14-08-21 10:48:40    246:1-pipe1                         :         $ send CLOSE_OK
D: 14-08-21 10:48:40    246:1-pipe1                         :         > start

Host "reader" (airbook.local)

Post started at: 14-08-21 10:48:38 Running tasks: 1

Test script

sleep 1
timeout 5000
open pipe1 read
read pipe1 3 abc
close pipe1 read

Script Log

14-08-21 10:48:39 Set prefix to 1
14-08-21 10:48:39 Set broker to 1-1
14-08-21 10:48:39 Sleeping for 1 seconds
14-08-21 10:48:40 Set timeout to 5000
14-08-21 10:48:40 Opening descriptor "1-1|1-pipe1"
14-08-21 10:48:40 Opened pipe "pipe1" for read
14-08-21 10:48:40 Reading 3 bytes from pipe "pipe1"
14-08-21 10:48:45 Unexpected exception: timeouterror
14-08-21 10:48:45 Test failed

Broker Log

GNU gdb (GDB) 7.4.1-debian
Copyright (C) 2012 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
Reading symbols from /opt/bundler/zvm2-zpipes/zvm2-zpipes-00009/bin/zbroker...done.
(gdb) (gdb) (gdb) Starting program: /opt/bundler/zvm2-zpipes/zvm2-zpipes-00009/bin/zbroker /tmp/tmpblFBXY/zbroker.cfg
warning: no loadable sections found in added symbol-file system-supplied DSO at 0x7ffff7ffa000
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
zbroker service/0.0.2
Copyright (c) 2014 the Contributors
This Software is provided under the MPLv2 License on an "as is" basis,
without warranty of any kind, either expressed, implied, or statutory.

I: 14-08-21 10:48:38 starting zpipes broker using config in '/tmp/tmpblFBXY/zbroker.cfg'
N: 14-08-21 10:48:38 starting zpipes service
I: 14-08-21 10:48:38 using TCP gossip discovery service
I: 14-08-21 10:48:38 gossip service connect to tcp://airbook.local:5672
[New Thread 0x7ffff65af700 (LWP 1606)]
[New Thread 0x7ffff5dae700 (LWP 1608)]
[New Thread 0x7ffff55ad700 (LWP 1609)]
[New Thread 0x7ffff4dac700 (LWP 1610)]
[New Thread 0x7ffff45ab700 (LWP 1611)]
I: 14-08-21 10:48:38 Zyre starting gossip discovery, endpoint=tcp://airbook.internal.pedde.com:49152
I: 14-08-21 10:48:38 joining cluster as 44D6FF
I: 14-08-21 10:48:38 ZPIPES server appeared at 7842BE
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:38 ZPIPES server vanished from AF8C22
I: 14-08-21 10:48:38 ZPIPES server appeared at AF8C22
I: 14-08-21 10:48:39 ZPIPES server vanished from 
I: 14-08-21 10:48:39 ZPIPES server vanished from 
D: 14-08-21 10:48:40    811:                                : start:
D: 14-08-21 10:48:40    811:                                :     INPUT
D: 14-08-21 10:48:40    811:                                :         $ lookup or create pipe
D: 14-08-21 10:48:40    811:1-pipe1                         :         $ open pipe reader
I: 14-08-21 10:48:40 1-pipe1: attach local reader
I: 14-08-21 10:48:40 1-pipe1: broadcast we are now reader
I: 14-08-21 10:48:40 open local reader
D: 14-08-21 10:48:40    811:1-pipe1                         :         > before reading
D: 14-08-21 10:48:40    811:1-pipe1                         : before reading:
D: 14-08-21 10:48:40    811:1-pipe1                         :     ok
D: 14-08-21 10:48:40    811:1-pipe1                         :         $ send INPUT_OK
D: 14-08-21 10:48:40    811:1-pipe1                         :         > reading
D: 14-08-21 10:48:40    811:1-pipe1                         : reading:
D: 14-08-21 10:48:40    811:1-pipe1                         :     READ
D: 14-08-21 10:48:40    811:1-pipe1                         :         $ process read request
D: 14-08-21 10:48:40    811:1-pipe1                         :         > processing read
I: 14-08-21 10:48:44 ZPIPES server vanished from AF8C22
D: 14-08-21 10:48:45    811:1-pipe1                         : processing read:
D: 14-08-21 10:48:45    811:1-pipe1                         :     wakeup
D: 14-08-21 10:48:45    811:1-pipe1                         :         $ send READ_TIMEOUT
D: 14-08-21 10:48:45    811:1-pipe1                         :         > reading

rpedde avatar Aug 21 '14 15:08 rpedde

Could you retest with latest masters of CZMQ and Zyre? We fixed an issue in Zyre today that was hitting beacon discovery.

This problem seems very familiar... #79 ...

hintjens avatar Aug 27 '14 19:08 hintjens