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>:
> 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
> > 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 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 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
> > INFO:bgpspeaker.api.base:API method network.add called with args:
> {'prefix': '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
> > INFO:bgpspeaker.api.base:API method network.add called with args:
> {'prefix': '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
> > 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 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 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
> > INFO:bgpspeaker.api.base:API method network.add called with args:
> {'prefix': '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
> > INFO:bgpspeaker.api.base:API method network.add called with args:
> {'prefix': '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: Stopping timer Peer State
> Summary Stats Timer
> > DEBUG:bgpspeaker.base:Peer: 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: 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>
> > 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>> のメール：
> >
> >> 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
> >> 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
> >> 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>> のメール：
> >>
> >>> 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
> >>>> 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
> >>>> 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
> >>>> DEBUG 2014-07-27 17:05:05,570 core 435 Closed connection to
> 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
> >>>> DEBUG 2014-07-27 17:05:45,524 core 435 Closed connection to
> 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
> >>>> DEBUG 2014-07-27 17:06:21,001 core 435 Closed connection to
> 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
> >>>> DEBUG 2014-07-27 17:07:06,263 core 435 Closed connection to
> 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>> のメール：
> >>>>
> >>>>> 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'}
> >>>>> INFO 2014-07-20 20:31:29,870 base 207 API method network.add called
> with args: {'prefix': '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'}
> >>>>> INFO 2014-07-20 20:31:29,872 base 207 API method network.add called
> with args: {'prefix': '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>> のメール：
> >>>>>
> >>>>>> 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>> 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'}
> >>>>>>> INFO 2014-07-20 19:07:29,061 base 207 API method network.add
> called with args: {'prefix': '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'}
> >>>>>>> INFO 2014-07-20 19:07:29,063 base 207 API method network.add
> called with args: {'prefix': '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>
> >>>> 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
> https://lists.sourceforge.net/lists/listinfo/ryu-devel
>
--
Satoshi KOBAYASHI <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
