problem: zbroker sometimes ignores read data

[rpedde]

Simple read/write, read side for some reason discarded the write data.

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

Host "writer" (airbook.local)

Post started at: 14-08-19 11:09:46
Running tasks: 1

Test script

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

Script Log

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

Broker Log

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-19 11:09:46 starting zpipes broker using config in '/tmp/tmpfEVqCt/zbroker.cfg'
N: 14-08-19 11:09:46 starting zpipes service
I: 14-08-19 11:09:46 using TCP gossip discovery service
I: 14-08-19 11:09:46 gossip service connect to tcp://airbook.local:5672
I: 14-08-19 11:09:46 Zyre node endpoint=tcp://*:49153 announce=tcp://airbook.internal.pedde.com:49153
I: 14-08-19 11:09:46 joining cluster as 895723
I: 14-08-19 11:09:46 ZPIPES server appeared at 895723
I: 14-08-19 11:09:46 ZPIPES server appeared at 6C6562
I: 14-08-19 11:09:46 ZPIPES server appeared at AA5C5F
D: 14-08-19 11:09:48    598:                                : start:
D: 14-08-19 11:09:48    598:                                :     OUTPUT
D: 14-08-19 11:09:48    598:                                :         $ lookup or create pipe
D: 14-08-19 11:09:48    598:1-pipe1                         :         $ open pipe writer
I: 14-08-19 11:09:48 1-pipe1: attach local writer
I: 14-08-19 11:09:48 1-pipe1: broadcast we are now writer
I: 14-08-19 11:09:48 open local writer
D: 14-08-19 11:09:48    598:1-pipe1                         :         > before writing
D: 14-08-19 11:09:48    598:1-pipe1                         : before writing:
D: 14-08-19 11:09:48    598:1-pipe1                         :     ok
D: 14-08-19 11:09:48    598:1-pipe1                         :         $ send OUTPUT_OK
D: 14-08-19 11:09:48    598:1-pipe1                         :         > writing
I: 14-08-19 11:09:48 peer=895723 command=HAVE WRITER pipe=1-pipe1 unicast=0
I: 14-08-19 11:09:48 1-pipe1: pipe already has writer: ignored
I: 14-08-19 11:09:48 peer=AA5C5F command=HAVE READER pipe=1-pipe1 unicast=0
I: 14-08-19 11:09:48 1-pipe1: attach remote reader
I: 14-08-19 11:09:48 1-pipe1: tell peer we are now writer
D: 14-08-19 11:09:48    598:1-pipe1                         : writing:
D: 14-08-19 11:09:48    598:1-pipe1                         :     have reader
D: 14-08-19 11:09:48    598:1-pipe1                         :         > writing
D: 14-08-19 11:09:48    598:1-pipe1                         : writing:
D: 14-08-19 11:09:48    598:1-pipe1                         :     WRITE
D: 14-08-19 11:09:48    598:1-pipe1                         :         $ process write request
D: 14-08-19 11:09:48    598:1-pipe1                         :         > processing write
D: 14-08-19 11:09:48    598:1-pipe1                         : processing write:
D: 14-08-19 11:09:48    598:1-pipe1                         :     have reader
D: 14-08-19 11:09:48    598:1-pipe1                         :         $ pass data to reader
I: 14-08-19 11:09:48 write 3 bytes
D: 14-08-19 11:09:48    598:1-pipe1                         :         $ send WRITE_OK
D: 14-08-19 11:09:48    598:1-pipe1                         :         > writing
I: 14-08-19 11:09:48 peer=AA5C5F command=HAVE READER pipe=1-pipe1 unicast=1
I: 14-08-19 11:09:48 1-pipe1: pipe already has reader: ignored
D: 14-08-19 11:09:48    598:1-pipe1                         : writing:
D: 14-08-19 11:09:48    598:1-pipe1                         :     CLOSE
D: 14-08-19 11:09:48    598:1-pipe1                         :         $ close pipe writer
I: 14-08-19 11:09:48 1-pipe1: tell peer we stopped being writer
I: 14-08-19 11:09:48 close local writer
D: 14-08-19 11:09:48    598:1-pipe1                         :         $ send CLOSE_OK
D: 14-08-19 11:09:48    598:1-pipe1                         :         > start
interrupted
N: 14-08-19 11:09:49 terminating zpipes service

Host "reader" (airbook.local)

Post started at: 14-08-19 11:09:46
Running tasks: 1

Test script

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

Script Log

14-08-19 11:09:47 Set prefix to 1
14-08-19 11:09:47 Set broker to 1-1
14-08-19 11:09:47 Sleeping for 1 seconds
14-08-19 11:09:48 Set timeout to 5000
14-08-19 11:09:48 Opening descriptor "1-1|1-pipe1"
14-08-19 11:09:48 Opened pipe "pipe1" for read
14-08-19 11:09:48 Reading 3 bytes from pipe "pipe1"
14-08-19 11:09:53 Unexpected exception: timeouterror
14-08-19 11:09:53 Test failed

Broker Log

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-19 11:09:46 starting zpipes broker using config in '/tmp/tmpQubN41/zbroker.cfg'
N: 14-08-19 11:09:46 starting zpipes service
I: 14-08-19 11:09:46 using TCP gossip discovery service
I: 14-08-19 11:09:46 gossip service connect to tcp://airbook.local:5672
I: 14-08-19 11:09:46 Zyre node endpoint=tcp://*:49152 announce=tcp://airbook.internal.pedde.com:49152
I: 14-08-19 11:09:46 joining cluster as AA5C5F
I: 14-08-19 11:09:46 ZPIPES server appeared at AA5C5F
I: 14-08-19 11:09:46 ZPIPES server appeared at 6C6562
I: 14-08-19 11:09:46 ZPIPES server appeared at 895723
D: 14-08-19 11:09:48    598:                                : start:
D: 14-08-19 11:09:48    598:                                :     INPUT
D: 14-08-19 11:09:48    598:                                :         $ lookup or create pipe
D: 14-08-19 11:09:48    598:1-pipe1                         :         $ open pipe reader
I: 14-08-19 11:09:48 1-pipe1: attach local reader
I: 14-08-19 11:09:48 1-pipe1: broadcast we are now reader
I: 14-08-19 11:09:48 open local reader
D: 14-08-19 11:09:48    598:1-pipe1                         :         > before reading
D: 14-08-19 11:09:48    598:1-pipe1                         : before reading:
D: 14-08-19 11:09:48    598:1-pipe1                         :     ok
D: 14-08-19 11:09:48    598:1-pipe1                         :         $ send INPUT_OK
D: 14-08-19 11:09:48    598:1-pipe1                         :         > reading
I: 14-08-19 11:09:48 peer=895723 command=HAVE WRITER pipe=1-pipe1 unicast=0
I: 14-08-19 11:09:48 1-pipe1: attach remote writer
I: 14-08-19 11:09:48 1-pipe1: tell peer we are now reader
D: 14-08-19 11:09:48    598:1-pipe1                         : reading:
D: 14-08-19 11:09:48    598:1-pipe1                         :     READ
D: 14-08-19 11:09:48    598:1-pipe1                         :         $ process read request
D: 14-08-19 11:09:48    598:1-pipe1                         :         > processing read
I: 14-08-19 11:09:48 peer=AA5C5F command=HAVE READER pipe=1-pipe1 unicast=0
I: 14-08-19 11:09:48 peer=895723 command=HAVE WRITER pipe=1-pipe1 unicast=1
I: 14-08-19 11:09:48 1-pipe1: attach remote writer
I: 14-08-19 11:09:48 peer=895723 command=DATA pipe=1-pipe1 unicast=1
I: 14-08-19 11:09:48 discard 3 bytes, unroutable
I: 14-08-19 11:09:48 peer=895723 command=DROP WRITER pipe=1-pipe1 unicast=1
D: 14-08-19 11:09:53    598:1-pipe1                         : processing read:
D: 14-08-19 11:09:53    598:1-pipe1                         :     wakeup
D: 14-08-19 11:09:53    598:1-pipe1                         :         $ send READ_TIMEOUT
D: 14-08-19 11:09:53    598:1-pipe1                         :         > reading
interrupted
N: 14-08-19 11:09:54 terminating zpipes service