openbmp
openbmp copied to clipboard
SNAS
Path attributes timestamp
Hello, team,
I found strange issue - when MySQL consumer trying to install path attributes for specific NLRI , for some of them it inserts it with wrong timestamp. All my routers are synchronized with NTP and timestamp for bgp peer is correct. Because my database partitioned by date, it confuses it.
I will try to catch tcpdump of real traffic to check if this is a Junos bug or not, but I see bgp_peer timestamp is ok so I assume it might be somewhere in code.
Here is the example: mysql> select * from bgp_peers where hash_id = '263f9f7c5584551428eba254d9350756'; +----------------------------------+----------------------------------+---------+--------+---------------+-----------------------------------------------+---------------+---------+-------+-------------+----------------------------+-------------+--------------+---------------+---------------+------------+-----------------+-----------+-------------+------------------+----------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------+------------+--------------+-----------------+------------+ | hash_id | router_hash_id | peer_rd | isIPv4 | peer_addr | name | peer_bgp_id | peer_as | state | isL3VPNpeer | timestamp | isPrePolicy | geo_ip_start | local_ip | local_bgp_id | local_port | local_hold_time | local_asn | remote_port | remote_hold_time | sent_capabilities | recv_capabilities | bmp_reason | bgp_err_code | bgp_err_subcode | error_text | +----------------------------------+----------------------------------+---------+--------+---------------+-----------------------------------------------+---------------+---------+-------+-------------+----------------------------+-------------+--------------+---------------+---------------+------------+-----------------+-----------+-------------+------------------+----------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------+------------+--------------+-----------------+------------+ | 263f9f7c5584551428eba254d9350756 | a21266dbc666a0409183bc3e2599197d | 0:0 | 1 | 10.252.128.22 | lo0-0.ams4-bk-intmx480-01 | 10.252.128.22 | 65502 | 1 | 0 | 2017-01-25 16:51:19.000000 | 1 | NULL | 10.252.128.21 | 10.252.128.21 | 54539 | 90 | 65502 | 179 | 90 | MPBGP (1) : afi=1 safi=1 : Unicast IPv4, Route Refresh Old (128), Route Refresh (2), Graceful Restart (64), 4 Octet ASN (65), 71 | MPBGP (1) : afi=1 safi=1 : Unicast IPv4, Route Refresh Old (128), Route Refresh (2), Graceful Restart (64), 4 Octet ASN (65), 71 | 0 | 0 | 0 | | +----------------------------------+----------------------------------+---------+--------+---------------+-----------------------------------------------+---------------+---------+-------+-------------+----------------------------+-------------+--------------+---------------+---------------+------------+-----------------+-----------+-------------+------------------+----------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------+------------+--------------+-----------------+------------+ 1 row in set (0.00 sec)
And failed try to install path attribute:
add 484363 fc00bbf629b183276f099c1bc14a7d1e a21266dbc666a0409183bc3e2599197d 10.193.131.111 263f9f7c5584551428eba254d9350756 10.252.128.22 65502 2017-12-17 21:08:43.000000 igp 65501 3356 14492 14492 3762 5 3762 10.252.128.22 2 100 0 1
Hi, Tim,
I've dumped raw bmp messages and there is no timestamp bigger than 1490000000. Not sure from where collector take 2017-12-17 .
@vladsker , would it be possible for you to send me the tcpdump of the bmp messages that have this issue? You mentioned "2017-12-17" was that supposed to be 2016-12-17?
JunOS is unlike other implementations of BMP when it comes to timestamps and how it sends the RIB DUMP. JunOS actually preserves the original received timestamps of NLRI's because JunOS is regenerating UPDATES based on the received table, which has the original timestamps from when the NLRI was last updated for that peer.
JunOS doesn't preserve the peer timestamp so when we get the peer UP for a peer it's the time at which the PEER_UP message was generated by JunOS. BUT... the NRLI's that follow are actually using the older timestamp of when the NLRI was last updated/received.
For the NLRI in question, when was that peer last established, was it before or on 2016-12-17
I quickly ran a test on my MX/JunOS 14.2R6.5. Below shows that the router has the older timestamp for the NLRI's and that timestamp is conveyed in BMP, while the PEER UP is the current timestamp. I'm using the BMP utils parsing script to parse the RAW BMP messages captured from the MX to show this.
In the below example, the prefix 200.1.1.7/32 has an age of 5d 10:11:37 which converted is UTC 2017-01-22 07:00:33 from when I ran the show command.
> show route 200.1.1.7/32 detail
inet.0: 45 destinations, 121 routes (45 active, 0 holddown, 29 hidden)
200.1.1.7/32 (2 entries, 1 announced)
*BGP Preference: 170/-101
Next hop type: Indirect
Address: 0x9796310
Next-hop reference count: 15
Source: 200.1.1.2
Next hop type: Router, Next hop index: 618
Next hop: 20.2.6.2 via xe-0/3/0.0, selected
Session Id: 0x140
Protocol next hop: 20.2.7.7
Indirect next hop: 0x9a4c330 1048576 INH Session ID: 0x143
State: <Active Int Ext>
Local AS: 100 Peer AS: 100
Age: 5d 10:11:37 Metric: 0 Metric2: 10
Validation State: unverified
Task: BGP_100.200.1.1.2+58982
Announcement bits (4): 0-KRT 5-BGP_RT_Background 6-Resolve tree 4 7-Resolve tree 5
AS path: 1 ?
Accepted
BMP: Pre: advertise Post: advertise Station: cra-tara-1
Localpref: 100
Router ID: 200.1.1.2
Notice the Age: 5d 10:11:37
I reset the BMP connection using (disable/enable) to cause JunOS to send BMP messages again. I then used tcpdump to capture those packets and run them through the quick and dirty parser script to validate.
Parsing 200.001.001.006.62601-172.017.000.002.05000
------------------------------------------------------------------
BMP = {'length': 182, 'version': 3, 'type': 'PEER_UP'}
| 2017-01-27 17:27:50.000000 1485538070.000000
| Peer addr = 200.1.1.5 asn = 100 bgp-id = 200.1.1.5
<... jumped to the message that contains 200.1.1.7/32 ...>
BMP = {'length': 117, 'version': 3, 'type': 'ROUTE_MON'}
| 2017-01-22 07:00:33.000000 1485068433.000000
| Peer addr = 200.1.1.5 asn = 100 bgp-id = 200.1.1.5
| ----------------------
| BGP = {'length': 56, 'type': 'UPDATE'}
Attribute is AS_PATH
4-octet encoding
| Update attr_len = 42 nlri_len = 14 nlri_prefixes = 2 wd_len = 0 wd_prefixes = 0
| preifx = 200.1.1.71/32
| preifx = 200.1.1.200/32
| ----------------------
Notice the NLRI (route monitor message) is using the older timestamp from when the NLRI was last updated in the router received table. This timestamp is older by 5 days than the peer up. In my case, the peer did in fact come up 5 days ago, so that matches.
Hi, Tim,
Thanks for detailed explanation.
I did capture for this issue and looks like RAW BMP messages correct timestamps. I've shared it with you on Google Drive, because file is near 200Mbytes.
But again, in Database those updates contain wrong timestamp:
add 1134792 ac21e07d2d1c03b096de8eb25d9bbded a21266dbc666a0409183bc3e2599197d 10.193.131.111 9c7e2672a18a4a4bcc8bcbaf32f0e92c fd00:2a01:5040:0:10:252:128:22 65502 2017-12-22 08:20:44.000000 igp 65501 10026 9824 3 9824 fd00:2a01:5040:0:10:252:128:22 2 200 10026:4200 10026:32392 10026:40044 10026:65006 43996:8714 0 0
12:43 add 1134979 88d58810024948d8c72fdf8d6e1b5875 a21266dbc666a0409183bc3e2599197d 10.193.131.111 408736a93ab99589e7d745bf822a582d 10.140.0.138 65505 2017-12-15 01:32:06.000000 igp 65505 65501 1299 9121 9121 15924 8386 7 8386 10.140.0.138 3 100 1299:30000 0 1
12:43 add 1138359 ae6220af6e9a91058627054f1f7c75c7 a21266dbc666a0409183bc3e2599197d 10.193.131.111 263f9f7c5584551428eba254d9350756 10.252.128.22 65502 2017-12-07 18:32:50.000000 igp 65501 65505 25415 3 25415 10.252.128.22 112 200 9033:3201 43996:9033 65011:11 0 1
add 1138361 9878077712e954e8f0a223da9fbbdbfc a21266dbc666a0409183bc3e2599197d 10.193.131.111 41e8dbca56983eaaaffe54818c911442 10.140.0.101 65501 2017-12-07 18:32:55.000000 igp 65501 65505 25415 3 25415 10.140.0.101 121 200 9033:3201 43996:9033 65011:11
12:43 add 1132835 75247b3660860d338dcbd474d3ec837b a21266dbc666a0409183bc3e2599197d 10.193.131.111 41e8dbca56983eaaaffe54818c911442 10.140.0.101 65501 2017-11-30 15:04:39.000000 igp 65501 1299 7018 5650 22390 5 22390 10.140.0.101 2 100 22390 13.15.47.254 1299:25000 0 1
12:44 add 1135045 c3718ee08594ed36d331d303cfed76d3 a21266dbc666a0409183bc3e2599197d 10.193.131.111 7efc7454e55a396c3b9705a481acc7fc 193.239.116.255 34307 2017-11-11 14:05:08.000000 igp 201290 1 201290 193.239.117.153 10 0 34307:13100 34307:13116 0 1
add 1135495 e66b220a66f610d4d69cec4bbd533255 a21266dbc666a0409183bc3e2599197d 10.193.131.111 263f9f7c5584551428eba254d9350756 10.252.128.22 65502 2017-11-11 14:05:12.000000 igp 6762 2914 12859 12654 4 12654 10.252.128.22 100 64723 10.38.216.137 6762:30 6762:14400
Thanks.
@vladsker, the link to google drive works but it gives me a 403/not authorized error when I try to download the file.
Based on your output above, it suggests the collector is the one decoding the wrong timestamps. I should be able to reproduce and fix this very quickly with your pcap.
I just sent you an email with a user/pw and IP to a server where you can SCP the pcap. Can you put it there?
The google drive error is:
403. That’s an error.
We're sorry, but you do not have access to this page. That’s all we know.
Thanks, Tim
@vladsker, received the pcap, thanks!
The pcap contained two flows, one from 10.193.131.93 and another from 10.193.131.111. The trace data from 10.193.131.111 showed only timestamps from 2017-01-30. This flow seemed fine.
The 10.193.131.93 flow on the other hand does have timestamps dating back to 11/11/2016, which does include the timestamps in 2016-12-14 and 2016-12-15. None of the timestamps are in the future as you wrote, 2017-12-15. I'm not sure how
TAB delimited output you showed above looks to be the "openbmp.parsed.base_attribute" output, which does show 2017-11-11 and 2017-12-07. This is is very odd because from your trace I do not see that.
I do see the dates with the correct year of 2016-11-11, 2016-12-14, and 2016-12-15.
below shows the base_attribute entry (column 9 is the timestamp)
I used awk to print column numbers with vertical representation.
[1 ]: add
[2 ]: 459
[3 ]: d6a4745e7bac8af34f44f054ce7dee68
[4 ]: 9b90e49e4c43c4b2b19d16b7bff928ff
[5 ]: 10.117.201.197
[6 ]: b76f3ea7a352cb9a6aaf13b0be7ceec6
[7 ]: 10.252.128.21
[8 ]: 65502
[9 ]: 2016-11-11 14:05:26.000000
[10 ]: igp
[11 ]: 6461 5511 2647 51964
[12 ]: 4
[13 ]: 51964
[14 ]: 10.252.128.21
[15 ]: 1
[16 ]: 100
[17 ]: 51964 10.230.62.194
[18 ]: 6461:5997
[19 ]:
[20 ]:
[21 ]: 0
[22 ]: 1
[23 ]:
Below is from the DB, which shows the same timestamp, still in 2016.
MariaDB [openBMP]> select timestamp from path_attrs limit 10;
+----------------------------+
| timestamp |
+----------------------------+
| 2016-12-15 01:03:34.000000 |
| 2016-12-15 02:43:11.000000 |
| 2016-12-15 01:31:15.000000 |
| 2016-12-15 02:43:11.000000 |
| 2016-12-15 00:03:07.000000 |
| 2016-12-14 21:57:26.000000 |
| 2016-12-15 01:07:07.000000 |
| 2016-12-15 01:03:34.000000 |
| 2016-12-15 01:05:06.000000 |
| 2016-12-15 01:08:52.000000 |
+----------------------------+
10 rows in set (0.00 sec)
Below is a decode of one of the updates showing that JunOS is sending the older timestamp as I mentioned earlier because it's regenerated using the original timestamp of the received UPDATE.
0000000 03 00 00 00 9f 00 00 80 00 00 00 00 00 00 00 00
First 6 bytes are the BMP common header, which defines BMP version 3, length of 159 bytes, type ROUTE-MONITOR.
The next and below are the BMP peer hearder.
Peer hearder type is global instance peer, L flag set (ipv6) pre-policy. No RD defined.
0000020 fd 00 2a 01 50 40 00 00 00 10 01 40 00 00 01 05
IPv6 addres is fd00:2a01:5040:0000:0010:0140:0000:0105
0000040 00 00 ff dd 0a fc 01 20 58 51 97 77 00 00 00 00
Peer AS is 65501, peer BGP-ID is 10.252.1.32.
Timestamp in seconds since epoch are bytes 58 51 97 77, which is
1,481,742,199 seconds, meaning 12/14/2016 @ 7:03pm (UTC).
The last 4 bytes are zero, which means no micro seconds provided.
Below is the BGP UPDATE packet, which is moot for this discussion since the timestamp is in the BMP peer header. BGP doesn't include timestamps.
0000060 ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff
0000100 00 6f 02 00 00 00 58 40 01 01 00 40 02 10 03 01
0000120 00 00 ff dd 02 02 00 00 1b 1b 00 00 02 41 80 04
0000140 04 00 00 00 01 40 05 04 00 00 00 c8 40 06 00 c0
0000160 07 08 00 00 02 41 40 e6 0f e0 c0 08 04 ab dc 22
0000200 0a 90 0e 00 1a 00 02 01 10 fd 00 2a 01 50 40 00
0000220 00 00 10 01 40 00 00 01 05 00 20 20 01 49 58
Hi, Tim,
Thanks for looking at. This is exactly what I mean. In BMP flow from the router I see correct timestamps, but when collector tries to wrote them to database, I see wrong timestamp.
Hi @vladsker , Circling back on this. We have confirmed that JunOS does send the older timestamps the collector and DB are loading them as they are received. All timestamps are processed and stored UTC. BMP protocol defines that the timestamps are UTC and we use that in the DB as well since you can change the DB per session to show the timestamp in anytime zone.
If you are still seeing that issue, can you send me a PCAP (tcpdump -s0 -w bmp.pcap tcp port 5000 and host
Hi, Tim,
I'll have a look and check.
Thanks.
On Thu, Feb 8, 2018 at 7:33 PM, Tim Evens [email protected] wrote:
Hi @vladsker https://github.com/vladsker , Circling back on this. We have confirmed that JunOS does send the older timestamps the collector and DB are loading them as they are received. All timestamps are processed and stored UTC. BMP protocol defines that the timestamps are UTC and we use that in the DB as well since you can change the DB per session to show the timestamp in anytime zone.
If you are still seeing that issue, can you send me a PCAP (tcpdump -s0 -w bmp.pcap tcp port 5000 and host ) where you see the timestamp being correct but being parsed incorrectly by the collector.
— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/OpenBMP/openbmp/issues/39#issuecomment-364206068, or mute the thread https://github.com/notifications/unsubscribe-auth/AXwsKaB76OG93bK2932VLUsViGYpIGjxks5tSz3ogaJpZM4Lt-gn .