Hi KOBAYASHI-san, Thanks for the comment.
Yeah, but I can't find where bgp codes touch one socket from multiple threads. When neighbor is reset, it close the internal socket, then create a new one. There are no simultaneous read I think. Thanks (2014/07/29 18:21), Satoshi KOBAYASHI wrote: > Hi ISHIDA-san, > > FYI. If it is a situation as an error message, the socket is read from > multiple green-threads. If that is right, it is not a bug of Eventlet but a > issue of a design of multithread. > > Thanks, > Satoshi > > 2014-07-29 17:54 GMT+09:00 ISHIDA Wataru <ishida.wat...@lab.ntt.co.jp > <mailto:ishida.wat...@lab.ntt.co.jp>>: > > Hi, > > Oh, I'm sorry. I haven't tested through rpc-cli. > I sent a patch that fix this problem. > > In spite of applying the patch, you may see a debug message like this. > > DEBUG 2014-07-29 08:40:33,527 speaker 566 Traceback (most recent call > last): > File "/home/wataru/ryu/ryu/services/protocols/bgp/speaker.py", line > 556, in _recv_loop > next_bytes = self._socket.recv(required_len) > File "/usr/local/lib/python2.7/dist-packages/eventlet/greenio.py", > line 264, in recv > timeout_exc=socket.timeout("timed out")) > File > "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/__init__.py", line 151, > in trampoline > listener = hub.add(hub.READ, fileno, current.switch) > File > "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/epolls.py", line 48, in > add > listener = BaseHub.add(self, evtype, fileno, cb) > File "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/hub.py", > line 126, in add > evtype, fileno, evtype)) > RuntimeError: Second simultaneous read on fileno 13 detected. Unless you > really know what you're doing, make sure that only one greenthread can read > any particular socket. Consider using a pools.Pool. If you do > know what you're doing and want to disable this error, call > eventlet.debug.hub_prevent_multiple_readers(False) > > This won't stop the bgpspeaker and it seems the connection will be reset > eventually, but take a little time. > I think this is a bug of eventlet. I'll make further investigation. > > Thanks, > > (2014/07/29 12:42), Toshiki Tsuboi wrote: > > HI > > > > It doesn’t work well in case of another test case . > > Additional report as follows . > > > > bast regards > > Toshiki Tsuboi > > > > ---- > > tsubo@RyuBGP:~/ryu/ryu/services/protocols/bgp/sampleApp$ sudo python > sampleBGPS.py > > INFO:bgpspeaker.api.base:API method core.start called with args: > {'router_id': '10.10.0.2', 'waiter': <ryu.lib.hub.Event object at > 0x7ffb02a08550>, 'bgp_server_port': 179, 'local_as': 64512, > 'refresh_max_eor_time': 0, 'refresh_stalepath_time': 0} > > DEBUG:utils.evtlet:Create CustomEvent called > > DEBUG:utils.evtlet:Create CustomEvent called > > DEBUG:bgpspeaker.processor:Starting new processing run... > > DEBUG:bgpspeaker.processor:Processing RT NLRI destination... > > DEBUG:bgpspeaker.processor:Processing destination... > > INFO:bgpspeaker.api.base:API method neighbor.create called with args: > {'remote_as': 64511, 'cap_mbgp_vpnv6': False, 'cap_mbgp_vpnv4': False, > 'cap_mbgp_ipv6': False, 'cap_mbgp_ipv4': True, 'next_hop': None, 'password': > None, 'ip_address': '192.168.100.100'} > > DEBUG:utils.evtlet:Create CustomEvent called > > DEBUG:utils.evtlet:Create CustomEvent called > > DEBUG:bgpspeaker.peer:Started peer Peer(ip: 192.168.100.100, asn: > 64511) > > DEBUG:bgpspeaker.peer:Peer 192.168.100.100 BGP FSM went from Idle to > Connect > > DEBUG:bgpspeaker.peer:Peer(ip: 192.168.100.100, asn: 64511) trying to > connect to ('192.168.100.100', 179) > > DEBUG:bgpspeaker.base:Connect TCP called for 192.168.100.100:179 > <http://192.168.100.100:179> > > DEBUG:bgpspeaker.speaker:Sent msg to ('192.168.100.100', '179') >> > BGPOpen(bgp_identifier='10.10.0.2',hold_time=40,len=41,my_as=64512,opt_param=[BGPOptParamCapabilityMultiprotocol(afi=1,cap_code=1,cap_length=4,length=6,reserved=0,safi=1,type=2), > > BGPOptParamCapabilityRouteRefresh(cap_code=2,cap_length=0,length=2,type=2)],opt_param_len=12,type=1,version=4) > > INFO:bgpspeaker.peer:Connection to peer: 192.168.100.100 established > > DEBUG:bgpspeaker.speaker:Received msg from ('192.168.100.100', '179') > << > BGPOpen(bgp_identifier='10.0.0.1',hold_time=180,len=45,my_as=64511,opt_param=[BGPOptParamCapabilityMultiprotocol(afi=1,cap_code=1,cap_length=4,length=6,reserved=0,safi=1,type=2), > > BGPOptParamCapabilityUnknown(cap_code=128,cap_length=0,cap_value='',length=2,type=2), > > BGPOptParamCapabilityRouteRefresh(cap_code=2,cap_length=0,length=2,type=2)],opt_param_len=16,type=1,version=4) > > DEBUG:bgpspeaker.peer:Peer 192.168.100.100 BGP FSM went from Connect > to OpenConfirm > > DEBUG:bgpspeaker.peer:Trying to bind protocol > <ryu.services.protocols.bgp.speaker.BgpProtocol object at 0x7ffb02955690> to > peer Peer(ip: 192.168.100.100, asn: 64511) > > DEBUG:bgpspeaker.peer:Connect retry event for Peer(ip: > 192.168.100.100, asn: 64511) is cleared > > DEBUG:bgpspeaker.speaker:Started keep-alive and expire timer for > negotiated holdtime 40 > > DEBUG:bgpspeaker.speaker:Sent msg to ('192.168.100.100', '179') >> > BGPKeepAlive(len=19,type=4) > > DEBUG:bgpspeaker.speaker:Received msg from ('192.168.100.100', '179') > << BGPKeepAlive(len=19,type=4) > > DEBUG:bgpspeaker.peer:Peer 192.168.100.100 BGP FSM went from > OpenConfirm to Established > > DEBUG:bgpspeaker.peer:Communicating current best path for all afi/safi > except 1/132 > > DEBUG:bgpspeaker.speaker:Received msg from ('192.168.100.100', '179') > << BGPUpdate(len=57,nlri=[BGPNLRI(addr='192.168.100.0',length=24), > BGPNLRI(addr='10.0.0.1',length=32)],path_attributes=[BGPPathAttributeOrigin(flags=64,length=1,type=1,value=2), > BGPPathAttributeAsPath(flags=64,length=4,type=2,value=[[64511]]), > BGPPathAttributeNextHop(flags=64,length=4,type=3,value='192.168.100.100'), > BGPPathAttributeMultiExitDisc(flags=128,length=4,type=4,value=0)],total_path_attribute_len=25,type=2,withdrawn_routes=[],withdrawn_routes_len=0) > > DEBUG:bgpspeaker.peer:NLRI: BGPNLRI(addr='192.168.100.0',length=24) > > DEBUG:bgpspeaker.peer:Extracted paths from Update msg.: Path(source: > Peer(ip: 192.168.100.100, asn: 64511), nlri: > BGPNLRI(addr='192.168.100.0',length=24), source ver#: 1, path attrs.: {1: > BGPPathAttributeOrigin(flags=64,length=1,type=1,value=2), 2: > BGPPathAttributeAsPath(flags=64,length=4,type=2,value=[[64511]]), 3: > BGPPathAttributeNextHop(flags=64,length=4,type=3,value='192.168.100.100'), 4: > BGPPathAttributeMultiExitDisc(flags=128,length=4,type=4,value=0)}, nexthop: > 192.168.100.100, is_withdraw: False) > > DEBUG:bgpspeaker.signals.base:SIGNAL: ('core', 'adj', 'rib', 'in', > 'changed') emited with data: {'peer': <ryu.services.protocols.bgp.peer.Peer > object at 0x7ffb029553d0>, 'received_route': > <ryu.services.protocols.bgp.model.ReceivedRoute object at 0x7ffb028fc5d0>} > > DEBUG:bgpspeaker.signals.base:SIGNAL: ('core', 'dest', 'changed') > emited with data: Destination(table: Ipv4Table(scope_id: None, rf: > RouteFamily(afi=1,safi=1)), nlri: BGPNLRI(addr='192.168.100.0',length=24), > paths: 0, withdraws: 0, new paths: 1) > > DEBUG:bgpspeaker.peer:NLRI: BGPNLRI(addr='10.0.0.1',length=32) > > DEBUG:bgpspeaker.peer:Extracted paths from Update msg.: Path(source: > Peer(ip: 192.168.100.100, asn: 64511), nlri: > BGPNLRI(addr='10.0.0.1',length=32), source ver#: 1, path attrs.: {1: > BGPPathAttributeOrigin(flags=64,length=1,type=1,value=2), 2: > BGPPathAttributeAsPath(flags=64,length=4,type=2,value=[[64511]]), 3: > BGPPathAttributeNextHop(flags=64,length=4,type=3,value='192.168.100.100'), 4: > BGPPathAttributeMultiExitDisc(flags=128,length=4,type=4,value=0)}, nexthop: > 192.168.100.100, is_withdraw: False) > > DEBUG:bgpspeaker.signals.base:SIGNAL: ('core', 'adj', 'rib', 'in', > 'changed') emited with data: {'peer': <ryu.services.protocols.bgp.peer.Peer > object at 0x7ffb029553d0>, 'received_route': > <ryu.services.protocols.bgp.model.ReceivedRoute object at 0x7ffb028fc790>} > > DEBUG:bgpspeaker.signals.base:SIGNAL: ('core', 'dest', 'changed') > emited with data: Destination(table: Ipv4Table(scope_id: None, rf: > RouteFamily(afi=1,safi=1)), nlri: BGPNLRI(addr='10.0.0.1',length=32), paths: > 0, withdraws: 0, new paths: 1) > > DEBUG:bgpspeaker.processor:Starting new processing run... > > DEBUG:bgpspeaker.processor:Processing RT NLRI destination... > > DEBUG:bgpspeaker.processor:Processing destination... > > DEBUG:bgpspeaker.info_base.base:Processing destination: > Destination(table: Ipv4Table(scope_id: None, rf: RouteFamily(afi=1,safi=1)), > nlri: BGPNLRI(addr='192.168.100.0',length=24), paths: 0, withdraws: 0, new > paths: 1) > > DEBUG:bgpspeaker.info_base.base:Removing 0 withdrawals > > DEBUG:bgpspeaker.info_base.base:New best path selected for destination > Destination(table: Ipv4Table(scope_id: None, rf: RouteFamily(afi=1,safi=1)), > nlri: BGPNLRI(addr='192.168.100.0',length=24), paths: 1, withdraws: 0, new > paths: 0) > > DEBUG:bgpspeaker.peer:Peer Peer(ip: 192.168.100.100, asn: 64511) asked > to communicate path > > DEBUG:bgpspeaker.peer:Skipping sending path as AS_PATH has peer AS > 64511 > > DEBUG:bgpspeaker.signals.base:SIGNAL: ('core', 'best', 'changed') > emited with data: {'path': Path(Peer(ip: 192.168.100.100, asn: 64511), > BGPNLRI(addr='192.168.100.0',length=24), 1, {1: > BGPPathAttributeOrigin(flags=64,length=1,type=1,value=2), 2: > BGPPathAttributeAsPath(flags=64,length=4,type=2,value=[[64511]]), 3: > BGPPathAttributeNextHop(flags=64,length=4,type=3,value='192.168.100.100'), 4: > BGPPathAttributeMultiExitDisc(flags=128,length=4,type=4,value=0)}, > 192.168.100.100, False), 'is_withdraw': False} > > the best path changed: 64511 192.168.100.0/24 > <http://192.168.100.0/24> 192.168.100.100 False > > DEBUG:bgpspeaker.info_base.base:Processing destination: > Destination(table: Ipv4Table(scope_id: None, rf: RouteFamily(afi=1,safi=1)), > nlri: BGPNLRI(addr='10.0.0.1',length=32), paths: 0, withdraws: 0, new paths: > 1) > > DEBUG:bgpspeaker.info_base.base:Removing 0 withdrawals > > DEBUG:bgpspeaker.info_base.base:New best path selected for destination > Destination(table: Ipv4Table(scope_id: None, rf: RouteFamily(afi=1,safi=1)), > nlri: BGPNLRI(addr='10.0.0.1',length=32), paths: 1, withdraws: 0, new paths: > 0) > > DEBUG:bgpspeaker.peer:Peer Peer(ip: 192.168.100.100, asn: 64511) asked > to communicate path > > DEBUG:bgpspeaker.peer:Skipping sending path as AS_PATH has peer AS > 64511 > > DEBUG:bgpspeaker.signals.base:SIGNAL: ('core', 'best', 'changed') > emited with data: {'path': Path(Peer(ip: 192.168.100.100, asn: 64511), > BGPNLRI(addr='10.0.0.1',length=32), 1, {1: > BGPPathAttributeOrigin(flags=64,length=1,type=1,value=2), 2: > BGPPathAttributeAsPath(flags=64,length=4,type=2,value=[[64511]]), 3: > BGPPathAttributeNextHop(flags=64,length=4,type=3,value='192.168.100.100'), 4: > BGPPathAttributeMultiExitDisc(flags=128,length=4,type=4,value=0)}, > 192.168.100.100, False), 'is_withdraw': False} > > the best path changed: 64511 10.0.0.1/32 <http://10.0.0.1/32> > 192.168.100.100 False > > DEBUG:bgpspeaker.speaker:Received msg from ('192.168.100.100', '179') > << BGPKeepAlive(len=19,type=4) > > DEBUG:bgpspeaker.speaker:Received msg from ('192.168.100.100', '179') > << BGPKeepAlive(len=19,type=4) > > add a new prefix 10.20.1.0/24 <http://10.20.1.0/24> > > INFO:bgpspeaker.api.base:API method network.add called with args: > {'prefix': '10.20.1.0/24 <http://10.20.1.0/24>'} > > DEBUG:bgpspeaker.signals.base:SIGNAL: ('core', 'dest', 'changed') > emited with data: Destination(table: Ipv4Table(scope_id: None, rf: > RouteFamily(afi=1,safi=1)), nlri: IPAddrPrefix(addr='10.20.1.0',length=24), > paths: 0, withdraws: 0, new paths: 1) > > DEBUG:bgpspeaker.processor:Starting new processing run... > > DEBUG:bgpspeaker.processor:Processing RT NLRI destination... > > DEBUG:bgpspeaker.processor:Processing destination... > > DEBUG:bgpspeaker.info_base.base:Processing destination: > Destination(table: Ipv4Table(scope_id: None, rf: RouteFamily(afi=1,safi=1)), > nlri: IPAddrPrefix(addr='10.20.1.0',length=24), paths: 0, withdraws: 0, new > paths: 1) > > DEBUG:bgpspeaker.info_base.base:Removing 0 withdrawals > > DEBUG:bgpspeaker.info_base.base:New best path selected for destination > Destination(table: Ipv4Table(scope_id: None, rf: RouteFamily(afi=1,safi=1)), > nlri: IPAddrPrefix(addr='10.20.1.0',length=24), paths: 1, withdraws: 0, new > paths: 0) > > DEBUG:bgpspeaker.peer:Peer Peer(ip: 192.168.100.100, asn: 64511) asked > to communicate path > > DEBUG:bgpspeaker.signals.base:SIGNAL: ('core', 'best', 'changed') > emited with data: {'path': Path(None, > IPAddrPrefix(addr='10.20.1.0',length=24), 1, OrderedDict([(1, > BGPPathAttributeOrigin(flags=0,length=None,type=1,value=0)), (2, > BGPPathAttributeAsPath(flags=0,length=None,type=2,value=[[]]))]), 0.0.0.0, > False), 'is_withdraw': False} > > DEBUG:bgpspeaker.signals.base:SIGNAL: ('core', 'adj', 'rib', 'out', > 'changed') emited with data: {'peer': <ryu.services.protocols.bgp.peer.Peer > object at 0x7ffb029553d0>, 'sent_route': > <ryu.services.protocols.bgp.model.SentRoute object at 0x7ffb028fcc10>} > > DEBUG:bgpspeaker.speaker:Sent msg to ('192.168.100.100', '179') >> > BGPUpdate(len=45,nlri=[IPAddrPrefix(addr='10.20.1.0',length=24)],path_attributes=[BGPPathAttributeNextHop(flags=64,length=4,type=3,value='192.168.100.102'), > BGPPathAttributeOrigin(flags=64,length=1,type=1,value=0), > BGPPathAttributeAsPath(flags=64,length=4,type=2,value=[[64512]])],total_path_attribute_len=18,type=2,withdrawn_routes=[],withdrawn_routes_len=0) > > DEBUG:bgpspeaker.speaker:Sent msg to ('192.168.100.100', '179') >> > BGPKeepAlive(len=19,type=4) > > DEBUG:bgpspeaker.speaker:Received msg from ('192.168.100.100', '179') > << BGPKeepAlive(len=19,type=4) > > add a new prefix 10.20.2.0/24 <http://10.20.2.0/24> > > INFO:bgpspeaker.api.base:API method network.add called with args: > {'prefix': '10.20.2.0/24 <http://10.20.2.0/24>'} > > DEBUG:bgpspeaker.signals.base:SIGNAL: ('core', 'dest', 'changed') > emited with data: Destination(table: Ipv4Table(scope_id: None, rf: > RouteFamily(afi=1,safi=1)), nlri: IPAddrPrefix(addr='10.20.2.0',length=24), > paths: 0, withdraws: 0, new paths: 1) > > INFO:bgpspeaker.api.base:API method core.reset_neighbor called with > args: {'ip_address': '192.168.100.100'} > > INFO:bgpspeaker.peer:Peer(ip: 192.168.100.100, asn: 64511) disabled > > DEBUG:bgpspeaker.signals.base:SIGNAL: ('error', 'bgp', > <ryu.services.protocols.bgp.peer.Peer object at 0x7ffb029553d0>) emited with > data: {'peer': <ryu.services.protocols.bgp.peer.Peer object at > 0x7ffb029553d0>, 'subcode': 2, 'code': 6, 'reason': 'Cease: Administrative > Shutdown'} > > ERROR:bgpspeaker.speaker:Sent notification to ('192.168.100.102', > '52986') >> > BGPNotification(data='',error_code=6,error_subcode=2,len=21,type=3) > > DEBUG:bgpspeaker.base:Stopping activity BgpProtocol True, > ('192.168.100.100', '179'), ('192.168.100.102', '52986'). > > DEBUG:bgpspeaker.base:BgpProtocol True, ('192.168.100.100', '179'), > ('192.168.100.102', '52986'): Stopping timer Holdtime Timer > > DEBUG:bgpspeaker.processor:Starting new processing run... > > DEBUG:bgpspeaker.processor:Processing RT NLRI destination... > > DEBUG:bgpspeaker.processor:Processing destination... > > DEBUG:bgpspeaker.info_base.base:Processing destination: > Destination(table: Ipv4Table(scope_id: None, rf: RouteFamily(afi=1,safi=1)), > nlri: IPAddrPrefix(addr='10.20.2.0',length=24), paths: 0, withdraws: 0, new > paths: 1) > > DEBUG:bgpspeaker.info_base.base:Removing 0 withdrawals > > DEBUG:bgpspeaker.info_base.base:New best path selected for destination > Destination(table: Ipv4Table(scope_id: None, rf: RouteFamily(afi=1,safi=1)), > nlri: IPAddrPrefix(addr='10.20.2.0',length=24), paths: 1, withdraws: 0, new > paths: 0) > > DEBUG:bgpspeaker.peer:Peer Peer(ip: 192.168.100.100, asn: 64511) asked > to communicate path > > DEBUG:bgpspeaker.signals.base:SIGNAL: ('core', 'best', 'changed') > emited with data: {'path': Path(None, > IPAddrPrefix(addr='10.20.2.0',length=24), 1, OrderedDict([(1, > BGPPathAttributeOrigin(flags=0,length=None,type=1,value=0)), (2, > BGPPathAttributeAsPath(flags=0,length=None,type=2,value=[[]]))]), 0.0.0.0, > False), 'is_withdraw': False} > > DEBUG:bgpspeaker.base:BgpProtocol True, ('192.168.100.100', '179'), > ('192.168.100.102', '52986'): Stopping timer Keepalive Timer > > DEBUG:bgpspeaker.signals.base:SIGNAL: ('core', 'adj', 'rib', 'out', > 'changed') emited with data: {'peer': <ryu.services.protocols.bgp.peer.Peer > object at 0x7ffb029553d0>, 'sent_route': > <ryu.services.protocols.bgp.model.SentRoute object at 0x7ffb028fcc90>} > > INFO:bgpspeaker.peer:Connection to peer 192.168.100.100 lost, reason: > failed to write to socket Resetting retry connect loop: False > > DEBUG:bgpspeaker.peer:Peer 192.168.100.100 BGP FSM went from > Established to Idle > > DEBUG:bgpspeaker.base:Stopping activity BgpProtocol True, > ('192.168.100.100', '179'), ('192.168.100.102', '52986'). > > DEBUG:bgpspeaker.base:BgpProtocol True, ('192.168.100.100', '179'), > ('192.168.100.102', '52986'): Stopping timer Holdtime Timer > > DEBUG:bgpspeaker.base:BgpProtocol True, ('192.168.100.100', '179'), > ('192.168.100.102', '52986'): Stopping timer Keepalive Timer > > DEBUG:bgpspeaker.base:BgpProtocol True, ('192.168.100.100', '179'), > ('192.168.100.102', '52986'): Closing socket passive_conn - > <eventlet.greenio.GreenSocket object at 0x7ffb02955710> > > DEBUG:bgpspeaker.base:Stopping activity BgpProtocol True, > ('192.168.100.100', '179'), ('192.168.100.102', '52986') finished. > > DEBUG:bgpspeaker.peer:Un-scheduling sending of initial Non-RTC UPDATEs > (init. UPDATEs already sent: False) > > DEBUG:bgpspeaker.core_managers.peer_manager:Cleaning obsolete paths > whose source/version: 192.168.100.100/2 <http://192.168.100.100/2> > > DEBUG:bgpspeaker.info_base.base:Cleaning paths from table > Ipv4Table(scope_id: None, rf: RouteFamily(afi=1,safi=1)) for peer Peer(ip: > 192.168.100.100, asn: 64511) > > DEBUG:bgpspeaker.info_base.base:Removed sent route > IPAddrPrefix(addr='10.20.1.0',length=24) for Peer(ip: 192.168.100.100, asn: > 64511) > > DEBUG:bgpspeaker.signals.base:SIGNAL: ('core', 'dest', 'changed') > emited with data: Destination(table: Ipv4Table(scope_id: None, rf: > RouteFamily(afi=1,safi=1)), nlri: BGPNLRI(addr='192.168.100.0',length=24), > paths: 0, withdraws: 0, new paths: 0) > > DEBUG:bgpspeaker.signals.base:SIGNAL: ('core', 'dest', 'changed') > emited with data: Destination(table: Ipv4Table(scope_id: None, rf: > RouteFamily(afi=1,safi=1)), nlri: BGPNLRI(addr='10.0.0.1',length=32), paths: > 0, withdraws: 0, new paths: 0) > > INFO:bgpspeaker.speaker:failed to write to socket > > DEBUG:bgpspeaker.speaker:Sent msg to ('192.168.100.100', '179') >> > BGPUpdate(len=45,nlri=[IPAddrPrefix(addr='10.20.2.0',length=24)],path_attributes=[BGPPathAttributeNextHop(flags=64,length=4,type=3,value='192.168.100.102'), > BGPPathAttributeOrigin(flags=64,length=1,type=1,value=0), > BGPPathAttributeAsPath(flags=64,length=4,type=2,value=[[64512]])],total_path_attribute_len=18,type=2,withdrawn_routes=[],withdrawn_routes_len=0) > > DEBUG:bgpspeaker.base:Stopping activity BgpProtocol True, > ('192.168.100.100', '179'), ('192.168.100.102', '52986') finished. > > DEBUG:bgpspeaker.peer:Disabling connect-retry as neighbor was disabled > > DEBUG:bgpspeaker.processor:Starting new processing run... > > DEBUG:bgpspeaker.processor:Processing RT NLRI destination... > > DEBUG:bgpspeaker.processor:Processing destination... > > DEBUG:bgpspeaker.info_base.base:Processing destination: > Destination(table: Ipv4Table(scope_id: None, rf: RouteFamily(afi=1,safi=1)), > nlri: BGPNLRI(addr='192.168.100.0',length=24), paths: 0, withdraws: 0, new > paths: 0) > > DEBUG:bgpspeaker.info_base.base:Removing 0 withdrawals > > DEBUG:bgpspeaker.signals.base:SIGNAL: ('core', 'best', 'changed') > emited with data: {'path': Path(Peer(ip: 192.168.100.100, asn: 64511), > BGPNLRI(addr='192.168.100.0',length=24), 1, {1: > BGPPathAttributeOrigin(flags=64,length=1,type=1,value=2), 2: > BGPPathAttributeAsPath(flags=64,length=4,type=2,value=[[64511]]), 3: > BGPPathAttributeNextHop(flags=64,length=4,type=3,value='192.168.100.100'), 4: > BGPPathAttributeMultiExitDisc(flags=128,length=4,type=4,value=0)}, > 192.168.100.100, False), 'is_withdraw': True} > > the best path changed: 64511 192.168.100.0/24 > <http://192.168.100.0/24> 192.168.100.100 True > > DEBUG:bgpspeaker.info_base.base:Processing destination: > Destination(table: Ipv4Table(scope_id: None, rf: RouteFamily(afi=1,safi=1)), > nlri: BGPNLRI(addr='10.0.0.1',length=32), paths: 0, withdraws: 0, new paths: > 0) > > DEBUG:bgpspeaker.info_base.base:Removing 0 withdrawals > > DEBUG:bgpspeaker.signals.base:SIGNAL: ('core', 'best', 'changed') > emited with data: {'path': Path(Peer(ip: 192.168.100.100, asn: 64511), > BGPNLRI(addr='10.0.0.1',length=32), 1, {1: > BGPPathAttributeOrigin(flags=64,length=1,type=1,value=2), 2: > BGPPathAttributeAsPath(flags=64,length=4,type=2,value=[[64511]]), 3: > BGPPathAttributeNextHop(flags=64,length=4,type=3,value='192.168.100.100'), 4: > BGPPathAttributeMultiExitDisc(flags=128,length=4,type=4,value=0)}, > 192.168.100.100, False), 'is_withdraw': True} > > the best path changed: 64511 10.0.0.1/32 <http://10.0.0.1/32> > 192.168.100.100 True > > INFO:bgpspeaker.peer:Peer(ip: 192.168.100.100, asn: 64511) enabled > > DEBUG:bgpspeaker.peer:Peer 192.168.100.100 BGP FSM went from Idle to > Connect > > DEBUG:bgpspeaker.peer:Starting connect loop as neighbor is enabled. > > add a new prefix 10.20.3.0/24 <http://10.20.3.0/24> > > INFO:bgpspeaker.api.base:API method network.add called with args: > {'prefix': '10.20.3.0/24 <http://10.20.3.0/24>'} > > DEBUG:bgpspeaker.signals.base:SIGNAL: ('core', 'dest', 'changed') > emited with data: Destination(table: Ipv4Table(scope_id: None, rf: > RouteFamily(afi=1,safi=1)), nlri: IPAddrPrefix(addr='10.20.3.0',length=24), > paths: 0, withdraws: 0, new paths: 1) > > DEBUG:bgpspeaker.processor:Starting new processing run... > > DEBUG:bgpspeaker.processor:Processing RT NLRI destination... > > DEBUG:bgpspeaker.processor:Processing destination... > > DEBUG:bgpspeaker.info_base.base:Processing destination: > Destination(table: Ipv4Table(scope_id: None, rf: RouteFamily(afi=1,safi=1)), > nlri: IPAddrPrefix(addr='10.20.3.0',length=24), paths: 0, withdraws: 0, new > paths: 1) > > DEBUG:bgpspeaker.info_base.base:Removing 0 withdrawals > > DEBUG:bgpspeaker.info_base.base:New best path selected for destination > Destination(table: Ipv4Table(scope_id: None, rf: RouteFamily(afi=1,safi=1)), > nlri: IPAddrPrefix(addr='10.20.3.0',length=24), paths: 1, withdraws: 0, new > paths: 0) > > DEBUG:bgpspeaker.peer:Peer Peer(ip: 192.168.100.100, asn: 64511) asked > to communicate path > > DEBUG:bgpspeaker.peer:Skipping sending path as peer is not in > ESTABLISHED state Path(source: None, nlri: > IPAddrPrefix(addr='10.20.3.0',length=24), source ver#: 1, path attrs.: > OrderedDict([(1, BGPPathAttributeOrigin(flags=0,length=None,type=1,value=0)), > (2, BGPPathAttributeAsPath(flags=0,length=None,type=2,value=[[]]))]), > nexthop: 0.0.0.0, is_withdraw: False) > > DEBUG:bgpspeaker.signals.base:SIGNAL: ('core', 'best', 'changed') > emited with data: {'path': Path(None, > IPAddrPrefix(addr='10.20.3.0',length=24), 1, OrderedDict([(1, > BGPPathAttributeOrigin(flags=0,length=None,type=1,value=0)), (2, > BGPPathAttributeAsPath(flags=0,length=None,type=2,value=[[]]))]), 0.0.0.0, > False), 'is_withdraw': False} > > add a new prefix 10.20.4.0/24 <http://10.20.4.0/24> > > INFO:bgpspeaker.api.base:API method network.add called with args: > {'prefix': '10.20.4.0/24 <http://10.20.4.0/24>'} > > DEBUG:bgpspeaker.signals.base:SIGNAL: ('core', 'dest', 'changed') > emited with data: Destination(table: Ipv4Table(scope_id: None, rf: > RouteFamily(afi=1,safi=1)), nlri: IPAddrPrefix(addr='10.20.4.0',length=24), > paths: 0, withdraws: 0, new paths: 1) > > INFO:bgpspeaker.api.base:API method core.stop called with args: {} > > DEBUG:bgpspeaker.base:Stopping activity UnknownActivity: 1406604748.82. > > DEBUG:bgpspeaker.base:UnknownActivity: 1406604748.82: Stopping child > activity core_service > > DEBUG:bgpspeaker.base:Stopping activity core_service. > > DEBUG:bgpspeaker.base:core_service: Stopping child activity Peer: > 192.168.100.100 > > DEBUG:bgpspeaker.base:Stopping activity Peer: 192.168.100.100. > > DEBUG:bgpspeaker.base:Peer: 192.168.100.100 <http://192.168.100.100>: > Stopping timer Peer State Summary Stats Timer > > DEBUG:bgpspeaker.base:Peer: 192.168.100.100 <http://192.168.100.100>: > Stopping child thread peer.process_outgoing > > DEBUG:bgpspeaker.processor:Starting new processing run... > > DEBUG:bgpspeaker.processor:Processing RT NLRI destination... > > DEBUG:bgpspeaker.processor:Processing destination... > > DEBUG:bgpspeaker.info_base.base:Processing destination: > Destination(table: Ipv4Table(scope_id: None, rf: RouteFamily(afi=1,safi=1)), > nlri: IPAddrPrefix(addr='10.20.4.0',length=24), paths: 0, withdraws: 0, new > paths: 1) > > DEBUG:bgpspeaker.info_base.base:Removing 0 withdrawals > > DEBUG:bgpspeaker.info_base.base:New best path selected for destination > Destination(table: Ipv4Table(scope_id: None, rf: RouteFamily(afi=1,safi=1)), > nlri: IPAddrPrefix(addr='10.20.4.0',length=24), paths: 1, withdraws: 0, new > paths: 0) > > DEBUG:bgpspeaker.peer:Peer Peer(ip: 192.168.100.100, asn: 64511) asked > to communicate path > > DEBUG:bgpspeaker.peer:Skipping sending path as peer is not in > ESTABLISHED state Path(source: None, nlri: > IPAddrPrefix(addr='10.20.4.0',length=24), source ver#: 1, path attrs.: > OrderedDict([(1, BGPPathAttributeOrigin(flags=0,length=None,type=1,value=0)), > (2, BGPPathAttributeAsPath(flags=0,length=None,type=2,value=[[]]))]), > nexthop: 0.0.0.0, is_withdraw: False) > > DEBUG:bgpspeaker.signals.base:SIGNAL: ('core', 'best', 'changed') > emited with data: {'path': Path(None, > IPAddrPrefix(addr='10.20.4.0',length=24), 1, OrderedDict([(1, > BGPPathAttributeOrigin(flags=0,length=None,type=1,value=0)), (2, > BGPPathAttributeAsPath(flags=0,length=None,type=2,value=[[]]))]), 0.0.0.0, > False), 'is_withdraw': False} > > DEBUG:bgpspeaker.base:Peer: 192.168.100.100 <http://192.168.100.100>: > Closing socket L: 192.168.100.102, R: 192.168.100.100 - > <eventlet.greenio.GreenSocket object at 0x7ffb02955710> > > DEBUG:bgpspeaker.base:Stopping activity Peer: 192.168.100.100 finished. > > DEBUG:bgpspeaker.base:core_service: Stopping child activity > BgpProtocol True, ('192.168.100.100', '179'), ('192.168.100.102', '52986') > > DEBUG:bgpspeaker.base:core_service: Stopping child activity > UnknownActivity: 1406604748.87 > > DEBUG:bgpspeaker.base:Stopping activity UnknownActivity: 1406604748.87. > > DEBUG:bgpspeaker.base:Stopping activity UnknownActivity: 1406604748.87 > finished. > > DEBUG:bgpspeaker.base:core_service: Stopping child thread > core_service_server@0.0.0.0 <mailto:core_service_server@0.0.0.0> > <mailto:core_service_server@0.0.0.0 <mailto:core_service_server@0.0.0.0>> > > DEBUG:bgpspeaker.base:core_service: Stopping child thread Peer: > 192.168.100.100 > > DEBUG:bgpspeaker.base:core_service: Stopping child thread BgpProtocol > True, ('192.168.100.100', '179'), ('192.168.100.102', '52986') > > INFO:bgpspeaker.speaker:Connection lost as protocol is no longer active > > DEBUG:bgpspeaker.base:core_service: Stopping child thread > UnknownActivity: 1406604748.87 > > DEBUG:bgpspeaker.base:Stopping activity core_service finished. > > DEBUG:bgpspeaker.base:UnknownActivity: 1406604748.82: Stopping child > thread core_service > > DEBUG:bgpspeaker.base:Stopping activity UnknownActivity: 1406604748.82 > finished. > > > > > > > > > > > > > > > > > > > > > > 2014/07/29 12:31、Toshiki Tsuboi <t.tsubo2...@gmail.com > <mailto:t.tsubo2...@gmail.com> <mailto:t.tsubo2...@gmail.com > <mailto:t.tsubo2...@gmail.com>>> のメール： > > > >> Hi > >> > >> I’ve tested in latest master branch . > >> But, it looks this issue has occurred again . > >> > >> regards > >> Toshiki Tsuboi > >> > >> > >> —---- test result as following --------- > >> > >> (1) starting My sampleApp ( changes log level from info to debug ) > >> > >> $ sudo ./start_RyuBGPSpeaker.sh > >> > >> ...(snip) > >> > >> DEBUG 2014-07-29 12:18:02,525 speaker 447 Received msg from > ('192.168.100.100', '179') << BGPKeepAlive(len=19,type=4) > >> DEBUG 2014-07-29 12:18:02,526 speaker 447 Received msg from > ('192.168.100.100', '179') << BGPKeepAlive(len=19,type=4) > >> DEBUG 2014-07-29 12:18:15,495 speaker 401 Sent msg to > ('192.168.100.100', '179') >> BGPKeepAlive(len=19,type=4) > >> DEBUG 2014-07-29 12:18:16,474 speaker 447 Received msg from > ('192.168.100.100', '179') << BGPKeepAlive(len=19,type=4) > >> DEBUG 2014-07-29 12:18:28,507 speaker 401 Sent msg to > ('192.168.100.100', '179') >> BGPKeepAlive(len=19,type=4) > >> DEBUG 2014-07-29 12:18:29,475 speaker 447 Received msg from > ('192.168.100.100', '179') << BGPKeepAlive(len=19,type=4) > >> DEBUG 2014-07-29 12:18:32,441 base 345 Connect request received from > client for port 127.0.0.1:35865 <http://127.0.0.1:35865> > >> CRITICAL 2014-07-29 12:18:32,444 net_ctrl 121 RPC Session to > ('127.0.0.1', 35865) started > >> DEBUG 2014-07-29 12:18:32,445 net_ctrl 199 NetworkController > processing outgoing request list. > >> DEBUG 2014-07-29 12:18:32,445 net_ctrl 166 NetworkController started > processing incoming messages > >> DEBUG 2014-07-29 12:18:38,527 net_ctrl 373 Request from > NetworkController<<: core.reset_neighbor [{'ip_address': '192.168.100.100'}] > >> INFO 2014-07-29 12:18:38,527 base 207 API method core.reset_neighbor > called with args: {'ip_address': '192.168.100.100'} > >> INFO 2014-07-29 12:18:38,527 peer 459 Peer(ip: 192.168.100.100, asn: > 64511) disabled > >> DEBUG 2014-07-29 12:18:38,527 base 11 SIGNAL: ('error', 'bgp', > <ryu.services.protocols.bgp.peer.Peer object at 0x7ff6fca70f50>) emited with > data: {'peer': <ryu.services.protocols.bgp.peer.Peer object at > 0x7ff6fca70f50>, 'subcode': 2, 'code': 6, 'reason': 'Cease: Administrative > Shutdown'} > >> ERROR 2014-07-29 12:18:38,528 speaker 376 Sent notification to > ('192.168.100.102', '52938') >> > BGPNotification(data='',error_code=6,error_subcode=2,len=21,type=3) > >> DEBUG 2014-07-29 12:18:38,528 base 305 Stopping activity BgpProtocol > True, ('192.168.100.100', '179'), ('192.168.100.102', '52938'). > >> DEBUG 2014-07-29 12:18:38,528 base 291 BgpProtocol True, > ('192.168.100.100', '179'), ('192.168.100.102', '52938'): Stopping timer > Holdtime Timer > >> DEBUG 2014-07-29 12:18:38,528 base 291 BgpProtocol True, > ('192.168.100.100', '179'), ('192.168.100.102', '52938'): Stopping timer > Keepalive Timer > >> DEBUG 2014-07-29 12:18:38,528 base 285 BgpProtocol True, > ('192.168.100.100', '179'), ('192.168.100.102', '52938'): Closing socket > passive_conn - <eventlet.greenio.GreenSocket object at 0x7ff6fca8ed50> > >> DEBUG 2014-07-29 12:18:38,528 base 317 Stopping activity BgpProtocol > True, ('192.168.100.100', '179'), ('192.168.100.102', '52938') finished. > >> DEBUG 2014-07-29 12:18:38,529 peer 209 Peer 192.168.100.100 BGP FSM > went from Established to Idle > >> DEBUG 2014-07-29 12:18:38,529 peer 475 Disabling connect-retry as > neighbor was disabled > >> DEBUG 2014-07-29 12:18:39,453 base 345 Connect request received from > client for port 127.0.0.1:35866 <http://127.0.0.1:35866> > >> DEBUG 2014-07-29 12:18:39,454 base 305 Stopping activity > UnknownActivity: 1406603912.44. > >> DEBUG 2014-07-29 12:18:39,454 base 276 UnknownActivity: > 1406603912.44: Stopping child thread net_ctrl._process_outgoing > >> DEBUG 2014-07-29 12:18:39,455 base 276 UnknownActivity: > 1406603912.44: Stopping child thread net_ctrl._process_incoming > >> DEBUG 2014-07-29 12:18:39,455 base 317 Stopping activity > UnknownActivity: 1406603912.44 finished. > >> CRITICAL 2014-07-29 12:18:39,456 net_ctrl 109 RPC Session to > ('127.0.0.1', 35865) stopped > >> CRITICAL 2014-07-29 12:18:39,456 net_ctrl 121 RPC Session to > ('127.0.0.1', 35866) started > >> DEBUG 2014-07-29 12:18:39,457 net_ctrl 199 NetworkController > processing outgoing request list. > >> DEBUG 2014-07-29 12:18:39,457 net_ctrl 166 NetworkController started > processing incoming messages > >> DEBUG 2014-07-29 12:18:39,457 net_ctrl 373 Request from > NetworkController<<: core.reset_neighbor [{'ip_address': '192.168.100.100'}] > >> INFO 2014-07-29 12:18:39,458 base 207 API method core.reset_neighbor > called with args: {'ip_address': '192.168.100.100'} > >> ERROR 2014-07-29 12:18:39,461 base 222 Traceback (most recent call > last): > >> File > "/usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/api/base.py", > line 220, in call > >> return call(**kwargs) > >> File > "/usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/api/core.py", > line 78, in reset_neighor > >> ' reset.' % ip_address) > >> RuntimeConfigError: 200.1 - Neighbor 192.168.100.100 is not enabled, > hence cannot reset. > >> > >> ERROR 2014-07-29 12:18:39,467 hub 60 hub: uncaught exception: > Traceback (most recent call last): > >> File "/usr/local/lib/python2.7/dist-packages/ryu/lib/hub.py", line > 52, in _launch > >> func(*args, **kwargs) > >> File > "/usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/net_ctrl.py", > line 171, in _process_incoming_msgs > >> msg_buff = self._recv() > >> File > "/usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/net_ctrl.py", > line 222, in _recv > >> return self._sock_wrap(self._socket.recv)(RPC_SOCK_BUFF_SIZE) > >> File > "/usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/net_ctrl.py", > line 230, in wrapper > >> ret = func(*args, **kwargs) > >> File "/usr/local/lib/python2.7/dist-packages/eventlet/greenio.py", > line 264, in recv > >> timeout_exc=socket.timeout("timed out")) > >> File > "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/__init__.py", line 151, > in trampoline > >> listener = hub.add(hub.READ, fileno, current.switch) > >> File > "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/epolls.py", line 48, in > add > >> listener = BaseHub.add(self, evtype, fileno, cb) > >> File "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/hub.py", > line 126, in add > >> evtype, fileno, evtype)) > >> RuntimeError: Second simultaneous read on fileno 11 detected. Unless > you really know what you're doing, make sure that only one greenthread can > read any particular socket. Consider using a pools.Pool. If you do know what > you're doing and want to disable this error, call > eventlet.debug.hub_prevent_multiple_readers(False) > >> > >> > >> (2) neighbor reset through RPC in Ryu-cli > >> > >> $ ./rpc_cli.py --peers=bgps=localhost:50002 > >> (Cmd) request bgps core.reset_neighbor [{'ip_address': > '192.168.100.100'}] > >> NOTIFICATION from bgps ['neighbor.state', {'state': 'Idle', > 'ip_address': '192.168.100.100'}] > >> NOTIFICATION from bgps ['neighbor.down', {'ip_address': > '192.168.100.100'}] > >> disconnected. trying to connect... > >> connected. retrying the request... > >> RPC ERROR 200.1 - Neighbor 192.168.100.100 is not enabled, hence > cannot reset. > >> > >> > >> > >> 2014/07/29 11:32、ISHIDA Wataru <ishida.wat...@lab.ntt.co.jp > <mailto:ishida.wat...@lab.ntt.co.jp> <mailto:ishida.wat...@lab.ntt.co.jp > <mailto:ishida.wat...@lab.ntt.co.jp>>> のメール： > >> > >>> Hi, > >>> > >>> Thanks for the report. > >>> I sent the patch to fix reset neighbor and already merged. > >>> Please try it out. > >>> > >>> thanks > >>> > >>> (2014/07/27 17:31), Toshiki Tsuboi wrote: > >>>> Hi > >>>> > >>>> I’ve tested again after adapting the following patch code . > >>>> But, this issue has not resolved now . > >>>> -> I’m not sure why RPC has disconnected between Ryu-cli and > NetworkController(net_ctrl) ,after receiving reset_neighbor . > >>>> > >>>> diff --git a/ryu/services/protocols/bgp/speaker.py > b/ryu/services/protocols/bgp/speaker.py > >>>> index 2c823f5..cfa8be7 100644 > >>>> --- a/ryu/services/protocols/bgp/speaker.py > >>>> +++ b/ryu/services/protocols/bgp/speaker.py > >>>> @@ -371,8 +371,8 @@ class BgpProtocol(Protocol, Activity): > >>>> reason = notification.reason > >>>> self._send_with_lock(notification) > >>>> self._signal_bus.bgp_error(self._peer, code, subcode, > reason) > >>>> - if len(self._localname()): > >>>> - LOG.error('Sent notification to %r >> %s' % > (self._localname(), > >>>> + if len(self._localname): > >>>> + LOG.error('Sent notification to %r >> %s' % > (self._localname, > >>>> > notification)) > >>>> self._socket.close() > >>>> > >>>> > >>>> I hope this report is useful for resolving the issue . > >>>> Best regards. > >>>> > >>>> Toshiki Tsuboi > >>>> > >>>> > >>>> —---- test result as following --------- > >>>> > >>>> (1) starting My sampleApp ( changes log level from info to debug ) > >>>> > >>>> $ sudo ./start_RyuBGPSpeaker.sh > >>>> > >>>> …(snip) > >>>> > >>>> DEBUG 2014-07-27 17:04:10,345 speaker 447 Received msg from > ('192.168.100.100', '179') << > BGPKeepAlive(len=19,marker='\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff',type=4) > >>>> DEBUG 2014-07-27 17:04:10,346 speaker 447 Received msg from > ('192.168.100.100', '179') << > BGPKeepAlive(len=19,marker='\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff',type=4) > >>>> DEBUG 2014-07-27 17:04:19,174 base 345 Connect request received > from client for port 127.0.0.1:42502 <http://127.0.0.1:42502> > >>>> CRITICAL 2014-07-27 17:04:19,185 net_ctrl 121 RPC Session to > ('127.0.0.1', 42502) started > >>>> DEBUG 2014-07-27 17:04:19,185 net_ctrl 199 NetworkController > processing outgoing request list. > >>>> DEBUG 2014-07-27 17:04:19,186 net_ctrl 166 NetworkController > started processing incoming messages > >>>> DEBUG 2014-07-27 17:04:19,186 net_ctrl 373 Request from > NetworkController<<: core.reset_neighbor [{'ip_address': '192.168.100.100'}] > >>>> INFO 2014-07-27 17:04:19,187 base 207 API method > core.reset_neighbor called with args: {'ip_address': '192.168.100.100'} > >>>> DEBUG 2014-07-27 17:04:19,187 peer 415 Peer Peer(ip: > 192.168.100.100, asn: 64511) configuration update event, enabled: False. > >>>> DEBUG 2014-07-27 17:04:19,188 base 11 SIGNAL: ('error', 'bgp', > <ryu.services.protocols.bgp.peer.Peer object at 0x7fc120a6c750>) emited with > data: {'peer': <ryu.services.protocols.bgp.peer.Peer object at > 0x7fc120a6c750>, 'subcode': 2, 'code': 6, 'reason': 'Cease: Administrative > Shutdown'} > >>>> ERROR 2014-07-27 17:04:19,188 speaker 376 Sent notification to > ('192.168.100.102', '59501') >> > BGPNotification(data='',error_code=6,error_subcode=2,len=21,marker='\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff',type=3) > >>>> DEBUG 2014-07-27 17:04:19,189 base 305 Stopping activity > BgpProtocol True, ('192.168.100.100', '179'), ('192.168.100.102', '59501'). > >>>> DEBUG 2014-07-27 17:04:19,189 base 291 BgpProtocol True, > ('192.168.100.100', '179'), ('192.168.100.102', '59501'): Stopping timer > Holdtime Timer > >>>> DEBUG 2014-07-27 17:04:19,189 base 291 BgpProtocol True, > ('192.168.100.100', '179'), ('192.168.100.102', '59501'): Stopping timer > Keepalive Timer > >>>> DEBUG 2014-07-27 17:04:19,190 base 285 BgpProtocol True, > ('192.168.100.100', '179'), ('192.168.100.102', '59501'): Closing socket > passive_conn - <eventlet.greenio.GreenSocket object at 0x7fc120a8a550> > >>>> DEBUG 2014-07-27 17:04:19,190 base 317 Stopping activity > BgpProtocol True, ('192.168.100.100', '179'), ('192.168.100.102', '59501') > finished. > >>>> DEBUG 2014-07-27 17:04:19,191 peer 439 Disabling connect-retry as > neighbor was disabled (True) > >>>> DEBUG 2014-07-27 17:04:19,774 base 345 Connect request received > from client for port 127.0.0.1:42503 <http://127.0.0.1:42503> > >>>> DEBUG 2014-07-27 17:04:19,775 base 305 Stopping activity > UnknownActivity: 1406448259.17. > >>>> DEBUG 2014-07-27 17:04:19,776 base 276 UnknownActivity: > 1406448259.17: Stopping child thread net_ctrl._process_outgoing > >>>> DEBUG 2014-07-27 17:04:19,776 base 276 UnknownActivity: > 1406448259.17: Stopping child thread net_ctrl._process_incoming > >>>> DEBUG 2014-07-27 17:04:19,776 base 317 Stopping activity > UnknownActivity: 1406448259.17 finished. > >>>> CRITICAL 2014-07-27 17:04:19,777 net_ctrl 109 RPC Session to > ('127.0.0.1', 42502) stopped > >>>> CRITICAL 2014-07-27 17:04:19,777 net_ctrl 121 RPC Session to > ('127.0.0.1', 42503) started > >>>> DEBUG 2014-07-27 17:04:19,778 net_ctrl 199 NetworkController > processing outgoing request list. > >>>> DEBUG 2014-07-27 17:04:19,779 net_ctrl 166 NetworkController > started processing incoming messages > >>>> DEBUG 2014-07-27 17:04:19,779 net_ctrl 373 Request from > NetworkController<<: core.reset_neighbor [{'ip_address': '192.168.100.100'}] > >>>> INFO 2014-07-27 17:04:19,780 base 207 API method > core.reset_neighbor called with args: {'ip_address': '192.168.100.100'} > >>>> ERROR 2014-07-27 17:04:19,783 base 222 Traceback (most recent call > last): > >>>> File > "/usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/api/base.py", > line 220, in call > >>>> return call(**kwargs) > >>>> File > "/usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/api/core.py", > line 79, in reset_neighor > >>>> ' reset.' % ip_address) > >>>> RuntimeConfigError: 200.1 - Neighbor 192.168.100.100 is not > enabled, hence cannot reset. > >>>> > >>>> ERROR 2014-07-27 17:04:19,790 hub 60 hub: uncaught exception: > Traceback (most recent call last): > >>>> File "/usr/local/lib/python2.7/dist-packages/ryu/lib/hub.py", > line 52, in _launch > >>>> func(*args, **kwargs) > >>>> File > "/usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/net_ctrl.py", > line 171, in _process_incoming_msgs > >>>> msg_buff = self._recv() > >>>> File > "/usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/net_ctrl.py", > line 222, in _recv > >>>> return self._sock_wrap(self._socket.recv)(RPC_SOCK_BUFF_SIZE) > >>>> File > "/usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/net_ctrl.py", > line 230, in wrapper > >>>> ret = func(*args, **kwargs) > >>>> File > "/usr/local/lib/python2.7/dist-packages/eventlet/greenio.py", line 264, in > recv > >>>> timeout_exc=socket.timeout("timed out")) > >>>> File > "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/__init__.py", line 151, > in trampoline > >>>> listener = hub.add(hub.READ, fileno, current.switch) > >>>> File > "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/epolls.py", line 48, in > add > >>>> listener = BaseHub.add(self, evtype, fileno, cb) > >>>> File > "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 126, in > add > >>>> evtype, fileno, evtype)) > >>>> RuntimeError: Second simultaneous read on fileno 11 detected. > Unless you really know what you're doing, make sure that only one greenthread > can read any particular socket. Consider using a pools.Pool. If you do know > what you're doing and want to disable this error, call > eventlet.debug.hub_prevent_multiple_readers(False) > >>>> > >>>> DEBUG 2014-07-27 17:05:05,569 base 345 Connect request received > from client for port 192.168.100.100:31791 <http://192.168.100.100:31791> > >>>> DEBUG 2014-07-27 17:05:05,570 core 435 Closed connection to > 192.168.100.100:31791 <http://192.168.100.100:31791> as it is not a > recognized peer. > >>>> DEBUG 2014-07-27 17:05:05,570 base 11 SIGNAL: ('error', 'bgp', > None) emited with data: {'peer': None, 'subcode': 5, 'code': 6, 'reason': > 'Cease: Connection Rejected'} > >>>> ERROR 2014-07-27 17:05:05,570 speaker 376 Sent notification to > ('192.168.100.102', '179') >> > BGPNotification(data='',error_code=6,error_subcode=5,len=21,marker='\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff',type=3) > >>>> DEBUG 2014-07-27 17:05:45,523 base 345 Connect request received > from client for port 192.168.100.100:16040 <http://192.168.100.100:16040> > >>>> DEBUG 2014-07-27 17:05:45,524 core 435 Closed connection to > 192.168.100.100:16040 <http://192.168.100.100:16040> as it is not a > recognized peer. > >>>> DEBUG 2014-07-27 17:05:45,524 base 11 SIGNAL: ('error', 'bgp', > None) emited with data: {'peer': None, 'subcode': 5, 'code': 6, 'reason': > 'Cease: Connection Rejected'} > >>>> ERROR 2014-07-27 17:05:45,524 speaker 376 Sent notification to > ('192.168.100.102', '179') >> > BGPNotification(data='',error_code=6,error_subcode=5,len=21,marker='\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff',type=3) > >>>> DEBUG 2014-07-27 17:06:21,000 base 345 Connect request received > from client for port 192.168.100.100:33990 <http://192.168.100.100:33990> > >>>> DEBUG 2014-07-27 17:06:21,001 core 435 Closed connection to > 192.168.100.100:33990 <http://192.168.100.100:33990> as it is not a > recognized peer. > >>>> DEBUG 2014-07-27 17:06:21,001 base 11 SIGNAL: ('error', 'bgp', > None) emited with data: {'peer': None, 'subcode': 5, 'code': 6, 'reason': > 'Cease: Connection Rejected'} > >>>> ERROR 2014-07-27 17:06:21,001 speaker 376 Sent notification to > ('192.168.100.102', '179') >> > BGPNotification(data='',error_code=6,error_subcode=5,len=21,marker='\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff',type=3) > >>>> DEBUG 2014-07-27 17:07:06,263 base 345 Connect request received > from client for port 192.168.100.100:11862 <http://192.168.100.100:11862> > >>>> DEBUG 2014-07-27 17:07:06,263 core 435 Closed connection to > 192.168.100.100:11862 <http://192.168.100.100:11862> as it is not a > recognized peer. > >>>> DEBUG 2014-07-27 17:07:06,264 base 11 SIGNAL: ('error', 'bgp', > None) emited with data: {'peer': None, 'subcode': 5, 'code': 6, 'reason': > 'Cease: Connection Rejected'} > >>>> ERROR 2014-07-27 17:07:06,264 speaker 376 Sent notification to > ('192.168.100.102', '179') >> > BGPNotification(data='',error_code=6,error_subcode=5,len=21,marker='\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff',type=3) > >>>> > >>>> > >>>> (2) neighbor reset through RPC in Ryu-cli > >>>> > >>>> $ ./rpc_cli.py --peers=bgps=localhost:50002 > >>>> (Cmd) request bgps core.reset_neighbor [{'ip_address': > '192.168.100.100'}] > >>>> disconnected. trying to connect... > >>>> connected. retrying the request... > >>>> RPC ERROR 200.1 - Neighbor 192.168.100.100 is not enabled, hence > cannot reset. > >>>> (Cmd) > >>>> > >>>> > >>>> > >>>> > >>>> 2014/07/27 10:10、Toshiki Tsuboi <t.tsubo2...@gmail.com > <mailto:t.tsubo2...@gmail.com> <mailto:t.tsubo2...@gmail.com > <mailto:t.tsubo2...@gmail.com>><mailto:t.tsubo2...@gmail.com > <mailto:t.tsubo2...@gmail.com>>> のメール： > >>>> > >>>>> Hi Fujita-san > >>>>> > >>>>> I have tested reset_neighbor after adapting patch/ code ./ > >>>>> /It looks to me the previous issue/ has r/esolved . / > >>>>> / -> BGP peering down properly , because Ryu-BGP sends > Notification Message”//administrative //shutdown” ,/ > >>>>> > >>>>> But, after that, /BGP peering has kept ‘Down ‘,/ > >>>>> / -> Please check the attach //“/wireshark_keep_peer_down" > >>>>> > >>>>> Best regards > >>>>> Toshiki Tsuboi > >>>>> > >>>>> > >>>>> —---- test result as following --------- > >>>>> > >>>>> (1) starting My sampleApp > >>>>> > >>>>> $ sudo ./start_RyuBGPSpeaker.sh > >>>>> INFO 2014-07-20 20:31:29,814 base 207 API method core.start called > with args: {'router_id': '10.10.0.2', 'label_range': (100, 100000), 'waiter': > <ryu.lib.hub.Event object at 0x7fe42269ca90>, 'local_as': 64512, > 'bgp_server_port': 179, 'refresh_max_eor_time': 0, 'refresh_stalepath_time': > 0} > >>>>> INFO 2014-07-20 20:31:29,868 base 207 API method neighbor.create > called with args: {'remote_as': 64511, 'ip_address': '192.168.100.100'} > >>>>> INFO 2014-07-20 20:31:29,869 base 207 API method network.add > called with args: {'prefix': '10.20.0.0/24 <http://10.20.0.0/24>'} > >>>>> INFO 2014-07-20 20:31:29,870 base 207 API method network.add > called with args: {'prefix': '10.30.0.0/24 <http://10.30.0.0/24>'} > >>>>> INFO 2014-07-20 20:31:29,871 base 207 API method network.add > called with args: {'prefix': '10.40.0.0/16 <http://10.40.0.0/16>'} > >>>>> INFO 2014-07-20 20:31:29,872 base 207 API method network.add > called with args: {'prefix': '10.50.0.0/16 <http://10.50.0.0/16>'} > >>>>> CRITICAL 2014-07-20 20:31:30,891 peer 1763 Connection to peer: > 192.168.100.100 established > >>>>> CRITICAL 2014-07-20 20:32:07,426 net_ctrl 121 RPC Session to > ('127.0.0.1', 41478) started > >>>>> INFO 2014-07-20 20:32:07,427 base 207 API method comm_conf.get > called with args: {} > >>>>> INFO 2014-07-20 20:32:28,828 base 207 API method > core.reset_neighbor called with args: {'ip_address': '192.168.100.100'} > >>>>> ERROR 2014-07-20 20:32:28,829 base 225 Traceback (most recent call > last): > >>>>> File > "/usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/api/base.py", > line 220, in call > >>>>> return call(**kwargs) > >>>>> File > "/usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/api/core.py", > line 71, in reset_neighor > >>>>> neigh_conf.enabled = False > >>>>> File > "/usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/rtconf/neighbors.py", > line 351, in enabled > >>>>> enable) > >>>>> File > "/usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/rtconf/base.py", > line 252, in _notify_listeners > >>>>> callback(ConfEvent(self, evt, value)) > >>>>> File > "/usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/peer.py", > line 433, in on_update_enabled > >>>>> BGP_ERROR_SUB_ADMINISTRATIVE_SHUTDOWN > >>>>> File > "/usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/speaker.py", > line 374, in send_notification > >>>>> if len(self._localname()): > >>>>> TypeError: 'tuple' object is not callable > >>>>> > >>>>> CRITICAL 2014-07-20 20:32:28,942 peer 1777 Connection to peer > 192.168.100.100 lost, reason: Peer closed connection Resetting retry connect > loop: False > >>>>> INFO 2014-07-20 20:32:28,944 speaker 600 Peer closed connection > >>>>> INFO 2014-07-20 20:32:57,340 base 207 API method comm_conf.get > called with args: {} > >>>>> ERROR 2014-07-20 20:33:16,802 hub 60 hub: uncaught exception: > Traceback (most recent call last): > >>>>> File "/usr/local/lib/python2.7/dist-packages/ryu/lib/hub.py", > line 52, in _launch > >>>>> func(*args, **kwargs) > >>>>> File > "/usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/core.py", > line 439, in start_protocol > >>>>> bgp_proto.send_notification(code, subcode) > >>>>> File > "/usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/speaker.py", > line 374, in send_notification > >>>>> if len(self._localname()): > >>>>> TypeError: 'tuple' object is not callable > >>>>> > >>>>> (snip) > >>>>> > >>>>> > >>>>> (2) neighbor reset through RPC in Ryu-cli > >>>>> > >>>>> (Cmd) request bgps comm_conf.get [{}] > >>>>> RESULT {'router_id': '10.10.0.2', 'label_range': [100, 100000], > 'local_as': 64512, 'bgp_conn_retry_time': 30, 'bgp_server_port': 179, > 'tcp_conn_timeout': 30, 'refresh_max_eor_time': 0, 'refresh_stalepath_time': > 0, 'maximum_paths_external_rtfilter_all': True} > >>>>> (Cmd) > >>>>> (Cmd) request bgps core.reset_neighbor [{'ip_address': > '192.168.100.100'}] > >>>>> RPC ERROR 500.1 - 'tuple' object is not callable > >>>>> (Cmd) NOTIFICATION from bgps ['neighbor.state', {'state': 'Idle', > 'ip_address': '192.168.100.100'}] > >>>>> > >>>>> (Cmd) request bgps comm_conf.get [{}] > >>>>> NOTIFICATION from bgps ['neighbor.down', {'ip_address': > '192.168.100.100'}] > >>>>> RESULT {'router_id': '10.10.0.2', 'label_range': [100, 100000], > 'local_as': 64512, 'bgp_conn_retry_time': 30, 'bgp_server_port': 179, > 'tcp_conn_timeout': 30, 'refresh_max_eor_time': 0, 'refresh_stalepath_time': > 0, 'maximum_paths_external_rtfilter_all': True} > >>>>> (Cmd) > >>>>> (Cmd) request bgps comm_conf.get [{}] > >>>>> RESULT {'router_id': '10.10.0.2', 'label_range': [100, 100000], > 'local_as': 64512, 'bgp_conn_retry_time': 30, 'bgp_server_port': 179, > 'tcp_conn_timeout': 30, 'refresh_max_eor_time': 0, 'refresh_stalepath_time': > 0, 'maximum_paths_external_rtfilter_all': True} > >>>>> > >>>>> > >>>>> > >>>>> > >>>>> <wireshark_keep_peer_down.png> > >>>>> > >>>>> > >>>>> > >>>>> > >>>>> > >>>>> 2014/07/27 8:35、FUJITA Tomonori <fujita.tomon...@lab.ntt.co.jp > <mailto:fujita.tomon...@lab.ntt.co.jp> <mailto:fujita.tomon...@lab.ntt.co.jp > <mailto:fujita.tomon...@lab.ntt.co.jp>><mailto:fujita.tomon...@lab.ntt.co.jp > <mailto:fujita.tomon...@lab.ntt.co.jp>>> のメール： > >>>>> > >>>>>> Hi, > >>>>>> > >>>>>> On Sun, 27 Jul 2014 08:00:18 +0900 > >>>>>> Toshiki Tsuboi <t.tsubo2...@gmail.com > <mailto:t.tsubo2...@gmail.com> <mailto:t.tsubo2...@gmail.com > <mailto:t.tsubo2...@gmail.com>><mailto:t.tsubo2...@gmail.com > <mailto:t.tsubo2...@gmail.com>>> wrote: > >>>>>> > >>>>>>> I have just found the bug for Ryu-bgp . > >>>>>>> Please let me share a bug report as follows > >>>>>> > >>>>>> Thanks for that! > >>>>>> > >>>>>>> (1) starting My sampleApp > >>>>>>> -> neighbor create succeed > >>>>>>> > >>>>>>> $ sudo ./start_RyuBGPSpeaker.sh > >>>>>>> INFO 2014-07-20 19:07:29,012 base 207 API method core.start > called with args: {'router_id': '10.10.0.2', 'label_range': (100, 100000), > 'waiter': <ryu.lib.hub.Event object at > >>>>>>> 0x7f8b8d8dba90>, 'local_as': 64512, 'bgp_server_port': 179, > 'refresh_max_eor_time': 0, 'refresh_stalepath_time': 0} > >>>>>>> INFO 2014-07-20 19:07:29,059 base 207 API method > neighbor.create called with args: {'remote_as': 64511, 'ip_address': > '192.168.100.100'} > >>>>>>> INFO 2014-07-20 19:07:29,060 base 207 API method network.add > called with args: {'prefix': '10.20.0.0/24 <http://10.20.0.0/24>'} > >>>>>>> INFO 2014-07-20 19:07:29,061 base 207 API method network.add > called with args: {'prefix': '10.30.0.0/24 <http://10.30.0.0/24>'} > >>>>>>> INFO 2014-07-20 19:07:29,062 base 207 API method network.add > called with args: {'prefix': '10.40.0.0/16 <http://10.40.0.0/16>'} > >>>>>>> INFO 2014-07-20 19:07:29,063 base 207 API method network.add > called with args: {'prefix': '10.50.0.0/16 <http://10.50.0.0/16>'} > >>>>>>> CRITICAL 2014-07-20 19:07:30,096 peer 1759 Connection to peer: > 192.168.100.100 established > >>>>>>> > >>>>>>> (2) neighbor reset through RPC in Ryu-cli > >>>>>>> -> RPC ERROR has occurred > >>>>>>> > >>>>>>> $ ./rpc_cli.py --peers=bgps=localhost:50002 > >>>>>>> (Cmd) request bgps core.reset_neighbor [{'ip_address': > '192.168.100.100'}] > >>>>>>> RPC ERROR 500.1 - global name 'BGP_ERROR_CEASE' is not defined > >>>>>> > >>>>>> How about the following (sorry, not tested)? > >>>>>> > >>>>>> diff --git a/ryu/services/protocols/bgp/peer.py > b/ryu/services/protocols/bgp/peer.py > >>>>>> index 4b3675a..03533d7 100644 > >>>>>> --- a/ryu/services/protocols/bgp/peer.py > >>>>>> +++ b/ryu/services/protocols/bgp/peer.py > >>>>>> @@ -57,6 +57,10 @@ from ryu.lib.packet.bgp import BGP_MSG_UPDATE > >>>>>> from ryu.lib.packet.bgp import BGP_MSG_KEEPALIVE > >>>>>> from ryu.lib.packet.bgp import BGP_MSG_ROUTE_REFRESH > >>>>>> > >>>>>> +from ryu.lib.packet.bgp import BGP_ERROR_CEASE > >>>>>> +from ryu.lib.packet.bgp import > BGP_ERROR_SUB_ADMINISTRATIVE_SHUTDOWN > >>>>>> +from ryu.lib.packet.bgp import > BGP_ERROR_SUB_CONNECTION_COLLISION_RESOLUTION > >>>>>> + > >>>>>> from ryu.lib.packet.bgp import BGPPathAttributeNextHop > >>>>>> from ryu.lib.packet.bgp import BGPPathAttributeAsPath > >>>>>> from ryu.lib.packet.bgp import BGPPathAttributeLocalPref > >>>>> > >>>> > >>>> > >>>> > >>>> > ------------------------------------------------------------------------------ > >>>> Want fast and easy access to all the code in your enterprise? Index > and > >>>> search up to 200,000 lines of code with a free copy of Black Duck > >>>> Code Sight - the same software that powers the world's largest code > >>>> search on Ohloh, the Black Duck Open Hub! Try it now. > >>>> http://p.sf.net/sfu/bds > >>>> > >>>> > >>>> > >>>> _______________________________________________ > >>>> Ryu-devel mailing list > >>>> Ryu-devel@lists.sourceforge.net > <mailto:Ryu-devel@lists.sourceforge.net> > <mailto:Ryu-devel@lists.sourceforge.net > <mailto:Ryu-devel@lists.sourceforge.net>> > >>>> https://lists.sourceforge.net/lists/listinfo/ryu-devel > >> > > > > > ------------------------------------------------------------------------------ > Infragistics Professional > Build stunning WinForms apps today! > Reboot your WinForms applications with our WinForms controls. > Build a bridge from your legacy apps to the future. > > http://pubads.g.doubleclick.net/gampad/clk?id=153845071&iu=/4140/ostg.clktrk > _______________________________________________ > Ryu-devel mailing list > Ryu-devel@lists.sourceforge.net <mailto:Ryu-devel@lists.sourceforge.net> > https://lists.sourceforge.net/lists/listinfo/ryu-devel > > > > > -- > Satoshi KOBAYASHI <satosh...@stratosphere.co.jp > <mailto:satosh...@stratosphere.co.jp>> ------------------------------------------------------------------------------ Infragistics Professional Build stunning WinForms apps today! Reboot your WinForms applications with our WinForms controls. Build a bridge from your legacy apps to the future. http://pubads.g.doubleclick.net/gampad/clk?id=153845071&iu=/4140/ostg.clktrk _______________________________________________ Ryu-devel mailing list Ryu-devel@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/ryu-devel
