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

Wed Jan 22 05:26:53 EST 2014

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.