[j-nsp] MX-480 BGP Open message error with unknown subcode.

Fri Jan 24 06:42:35 EST 2014

This issue resolved by adding multihop stanza to neighbor, which is 
pretty weird, as peers use directly connected interface IPs ...

Misak Khachatryan wrote:
> Hello,
>
> I have strange problem on my MX-480. From some time router suddenly
> drops BGP peering with two customers and session doesn't come up from
> that time. One peer is IPv4, another one IPv6. Not configuration change
> done. There are lot of other BGP peers working OK on that router.
>
> Here is excerpt from log of one BGP session:
>
>
> Jan 22 12:46:34.412693 bgp_event: peer 2a02:2a50:0:11::2 (External AS
> 47623) old state Idle event Start new state Active
> Jan 22 12:46:34.412703 task_timer_ucreate: created timer
> BGP_47623_49800.2a02:2a50:0:11::2_Connect  flags <>
> Jan 22 12:46:34.412713 task_timer_uset: timer
> BGP_47623_49800.2a02:2a50:0:11::2_Connect <Touched> set to offset 2:28
> at 12:49:02
> Jan 22 12:47:37.567137
> Jan 22 12:47:37.567137 BGP RECV 2a02:2a50:0:11::2+59259 ->
> 2a02:2a50:0:11::1+179
> Jan 22 12:47:37.567190 BGP RECV message type 1 (Open) length 45
> Jan 22 12:47:37.567198 BGP RECV version 4 as 47623 holdtime 180 id
> 93.187.163.1 parmlen 16
> Jan 22 12:47:37.567204 BGP RECV Refresh capability, code=2
> Jan 22 12:47:37.567210 BGP RECV 4 Byte AS-Path capability (65), as_num
> 47623
> Jan 22 12:47:37.567215 BGP RECV MP capability AFI=2, SAFI=1
> Jan 22 12:47:37.567252 task_timer_delete:
> BGP_47623_49800.2a02:2a50:0:11::2_Connect <Touched>
> Jan 22 12:47:37.567267 task_set_socket: task
> BGP_47623_49800.2a02:2a50:0:11::2 socket 112
> Jan 22 12:47:37.567278 task_set_option_internal: task
> BGP_47623_49800.2a02:2a50:0:11::2 socket 112 option RecvBuffer(0) value
> 16384
> Jan 22 12:47:37.567287 task_set_option_internal: task
> BGP_47623_49800.2a02:2a50:0:11::2 socket 112 option SendBuffer(1) value
> 16384
> Jan 22 12:47:37.567309 task_set_option_internal: task
> BGP_47623_49800.2a02:2a50:0:11::2+59259 socket 112 option
> PathMTUDiscovery(26) value 0
> Jan 22 12:47:37.567333 task_set_option_internal: task
> BGP_47623_49800.2a02:2a50:0:11::2+59259 socket 112 option DontRoute(5)
> value 1
> Jan 22 12:47:37.567342 task_set_option_internal: task
> BGP_47623_49800.2a02:2a50:0:11::2+59259 socket 112 option
> IifRestrict(36) value 1
> Jan 22 12:47:37.567351 task_set_option_internal: task
> BGP_47623_49800.2a02:2a50:0:11::2+59259 socket 112 option TTL(15) value 1
> Jan 22 12:47:37.567362 task_timer_ucreate: created timer
> BGP_47623_49800.2a02:2a50:0:11::2+59259_Hold  flags <>
> Jan 22 12:47:37.567373 task_timer_uset: timer
> BGP_47623_49800.2a02:2a50:0:11::2+59259_Hold <Touched> set to offset
> 1:30 at 12:49:07
> Jan 22 12:47:37.567382 bgp_event: peer 2a02:2a50:0:11::2 (External AS
> 47623) old state Active event Open new state OpenSent
> Jan 22 12:47:37.567391 advertising graceful restart
> receiving-speaker-only capability to neighbor 2a02:2a50:0:11::2
> (External AS 47623)
> Jan 22 12:47:37.567401 bgp_4byte_aspath_add_cap():153 AS4-Peer
> 2a02:2a50:0:11::2 (External AS 47623)(SEND): 4 byte AS capability added,
> AS 49800
> Jan 22 12:47:37.567408 bgp_send: sending 59 bytes to 2a02:2a50:0:11::2
> (External AS 47623)
> Jan 22 12:47:37.567414
> Jan 22 12:47:37.567414 BGP SEND 2a02:2a50:0:11::1+179 ->
> 2a02:2a50:0:11::2+59259
> Jan 22 12:47:37.567421 BGP SEND message type 1 (Open) length 59
> Jan 22 12:47:37.567427 BGP SEND version 4 as 49800 holdtime 90 id
> 46.19.96.5 parmlen 30
> Jan 22 12:47:37.567432 BGP SEND MP capability AFI=2, SAFI=1
> Jan 22 12:47:37.567436 BGP SEND Refresh capability, code=128
> Jan 22 12:47:37.567440 BGP SEND Refresh capability, code=2
> Jan 22 12:47:37.567445 BGP SEND Restart capability, code=64, time=120,
> flags=
> Jan 22 12:47:37.567450 BGP SEND 4 Byte AS-Path capability (65), as_num
> 49800
> Jan 22 12:47:37.567490 bgp_process_4byte_aspath_cap():286 AS4-Peer
> 2a02:2a50:0:11::2 (External AS 47623)(RECV): 4 byte AS Cap value stored
> 47623
>
> Jan 22 12:47:37.567499 bgp_event: peer 2a02:2a50:0:11::2 (External AS
> 47623) old state OpenSent event RecvOpen new state OpenConfirm
> Jan 22 12:47:37.567504 bgp_send: sending 19 bytes to 2a02:2a50:0:11::2
> (External AS 47623)
> Jan 22 12:47:37.567517
> Jan 22 12:47:37.567517 BGP SEND 2a02:2a50:0:11::1+179 ->
> 2a02:2a50:0:11::2+59259
> Jan 22 12:47:37.567524 BGP SEND message type 4 (KeepAlive) length 19
> Jan 22 12:47:37.567533 bgp_recv_change: peer 2a02:2a50:0:11::2 (External
> AS 47623) receiver changed to bgp_recv_open
> Jan 22 12:47:37.567540 task_set_socket: task
> BGP_47623_49800.2a02:2a50:0:11::2+59259 socket 112
> Jan 22 12:47:37.568371 task_process_events: recv ready for
> BGP_47623_49800.2a02:2a50:0:11::2+59259
> Jan 22 12:47:37.568378 bgp_recv_open: called for peer 2a02:2a50:0:11::2
> (External AS 47623)
> Jan 22 12:47:37.568387
> Jan 22 12:47:37.568387 BGP RECV 2a02:2a50:0:11::2+59259 ->
> 2a02:2a50:0:11::1+179
> Jan 22 12:47:37.568395 BGP RECV message type 4 (KeepAlive) length 19
> Jan 22 12:47:37.568426 bgp_peer_established:6685: NOTIFICATION sent to
> 2a02:2a50:0:11::2 (External AS 47623): code 2 (Open Message Error),
> Reason: pending close
> Jan 22 12:47:37.568433 bgp_send: sending 21 bytes to 2a02:2a50:0:11::2
> (External AS 47623)
> Jan 22 12:47:37.568439
> Jan 22 12:47:37.568439 BGP SEND 2a02:2a50:0:11::1+179 ->
> 2a02:2a50:0:11::2+59259
> Jan 22 12:47:37.568446 BGP SEND message type 3 (Notification) length 21
> Jan 22 12:47:37.568451 BGP SEND Notification code 2 (Open Message Error)
> subcode 0 (unspecified error)
> Jan 22 12:47:37.568461 bgp_peer_close: closing peer 2a02:2a50:0:11::2
> (External AS 47623), state is 5 (OpenConfirm)
> Jan 22 12:47:37.568474 bgp_close_socket: peer 2a02:2a50:0:11::2
> (External AS 47623)
> Jan 22 12:47:37.568480 task_close: close socket 112 task
> BGP_47623_49800.2a02:2a50:0:11::2+59259
> Jan 22 12:47:37.568486 task_reset_socket: task
> BGP_47623_49800.2a02:2a50:0:11::2+59259 socket 112
> Jan 22 12:47:37.568518 task_timer_delete:
> BGP_47623_49800.2a02:2a50:0:11::2_Hold <Touched>
> Jan 22 12:47:37.568526 bgp_event: peer 2a02:2a50:0:11::2 (External AS
> 47623) old state OpenConfirm event OpenFail new state Idle
> Jan 22 12:47:37.568718 bgp_event: peer 2a02:2a50:0:11::2 (External AS
> 47623) old state Idle event Start new state Active
> Jan 22 12:47:37.568733 task_timer_ucreate: created timer
> BGP_47623_49800.2a02:2a50:0:11::2_Connect  flags <>
> Jan 22 12:47:37.568743 task_timer_uset: timer
> BGP_47623_49800.2a02:2a50:0:11::2_Connect <Touched> set to offset 2:28
> at 12:50:05
>
>
> Any clue? Thanks in advance.
>

-- 
Best regards,
Misak Khachatryan,
Head of Network Administration
and Monitoring Department,
GNC-Alfa CJSC.