Possible issue in serial sequences on current RADB NRTM

[dhutchin-ctl]

Describe the bug
It looks like serial numbers can sometimes be corrupted. Once they are corrupted, NRTM processing of further updates fails. The LEVEL3 instance of IRRdv4 is mirroring RADB. Consider the following entries from irrd.log (grep RADB):

2023-12-04 13:39:13,137 irrd[210576]: [irrd.mirroring.scheduler#DEBUG] Started new process RPSLMirrorImportUpdateRunner-RADB for mirror import/export for RADB
2023-12-04 13:39:13,175 irrd[1188550]: [irrd.mirroring.mirror_runners_import#DEBUG] Most recent mirrored serial for RADB: 255031, force_reload: False, nrtm enabled: True
2023-12-04 13:39:13,176 irrd[1188550]: [irrd.mirroring.mirror_runners_import#INFO] Retrieving NRTM updates for RADB from serial 255032 on nrtm.radb.net:43
2023-12-04 13:39:13,176 irrd[1188550]: [irrd.utils.whois_client#DEBUG] Running whois query -g RADB:3:255032-LAST on nrtm.radb.net port 43
2023-12-04 13:39:13,300 irrd[1188550]: [irrd.mirroring.mirror_runners_import#DEBUG] Received NRTM response for RADB: % Warning: there are no newer updates available

Above is the last entries where I got expected behavior. The "import_timer" seconds (900) later the following occurred.

2023-12-04 13:54:14,468 irrd[210576]: [irrd.mirroring.scheduler#DEBUG] Started new process RPSLMirrorImportUpdateRunner-RADB for mirror import/export for RADB
2023-12-04 13:54:14,506 irrd[1189565]: [irrd.mirroring.mirror_runners_import#DEBUG] Most recent mirrored serial for RADB: 255031, force_reload: False, nrtm enabled: True
2023-12-04 13:54:14,507 irrd[1189565]: [irrd.mirroring.mirror_runners_import#INFO] Retrieving NRTM updates for RADB from serial 255032 on nrtm.radb.net:43
2023-12-04 13:54:14,508 irrd[1189565]: [irrd.utils.whois_client#DEBUG] Running whois query -g RADB:3:255032-LAST on nrtm.radb.net port 43
2023-12-04 13:54:14,622 irrd[1189565]: [irrd.mirroring.mirror_runners_import#DEBUG] Received NRTM response for RADB: %% ERROR: Serials 255032 - 268299 do not exist

Starting at 2023-12-04 13:54:14, "255032-LAST" seems to be interpreted as "255032 - 268299" and produces an error about non-existent serials. The error persisted (for over 24 hours) until I performed "irrd_mirror_force_reload RADB". Some RADB updates were missed during this period. The updates were recovered when I did the force_reload. I suspect (without great evidence) that the error occurred in RADB's instance of IRRd. I have seen this same situation more than a year ago (so long before IRRdv4 4.4.2). I don't know if I am running the same version of IRRd now as I was the last time I saw this (but maybe).

To Reproduce
nrtm_host is set to nrtm.radb.net
Unknown how to reproduce the problem

Expected behaviour

IRRd version you are running
I am running IRRdv4 4.2.6, I don't know what version RADB is running (suspect 4.4.2)

Additional context
None

[troy2914]

NTT is seeing the same thing on 4.2.8

[troy2914]

And for the record we have had to irrd_mirror_force_reload RADB at least 3 times since their cutover.

[dhutchin-ctl]

I have had a total of 5 instances where we got into this mode since November of 2022. Below is the fist error message in each of the instances. Maybe these match up with Troy2914's instances:

2022-11-02 01:50:33,793 irrd[1845133]: [irrd.mirroring.mirror_runners_import#DEBUG] Received NRTM response for LACNIC: %% ERROR: Serials 103009 - 110626 do not exist
2023-11-13 18:02:33,554 irrd[3741814]: [irrd.mirroring.mirror_runners_import#DEBUG] Received NRTM response for RADB: %% ERROR: Serials 50 - 22293297 do not exist
2023-11-17 22:17:22,884 irrd[2275035]: [irrd.mirroring.mirror_runners_import#DEBUG] Received NRTM response for RADB: %% ERROR: Serials 47968 - 57319 do not exist
2023-11-25 03:48:12,089 irrd[1533810]: [irrd.mirroring.mirror_runners_import#DEBUG] Received NRTM response for RADB: %% ERROR: Serials 115384 - 123994 do not exist
2023-12-05 03:10:27,547 irrd[1687948]: [irrd.mirroring.mirror_runners_import#DEBUG] Received NRTM response for RADB: %% ERROR: Serials 255032 - 268299 do not exist

[dhutchin-ctl]

In my log file, I only see "Received NRTM response for ... Serials .... do not exist" occasionally. For instance, the RADB lines above. However, for queries to the LEVEL3 IRR, I see "encountered parsing error while parsing query "-g LEVEL3.... Serials .... do not exist" all the time. In all the cases where the query is TO the LEVEL3 IRR, the query range is and the reported non-existent serials is in the range of a small number to the number specified in the query. This is not the case with the RADB queries.

[mxsasha]

This is an interesting one. Given that you both experience issues, and some people raised issues about the IRRexplorer instance, a best guess is that RADB's NRTM streams are the common part here. I'll see if my own logs show anything on this. Also wondering if @schelcj has ideas, or whether the timings align with something? I do not know RADB's config, or whether they do anything unusual.

Current implementation

Let me run through how this is implemented so we all know precisely what messages mean and for my own overview.
Some of these choices may not be the clearest, but were made for backwards compatibility.

On the client side, IRRD keeps a serial_newest_mirror which only relates to the mirror source. When running NRTM, it requests (serial_newest_mirror+1)-LAST, and logs the response. Received NRTM messages are processed by the NRTMStreamParser, which also updates serial_newest_seen to be the highest serial from the NRTM ADD/DEL operations in the response. This means that we expect NRTMv3 clients to request non-existing serials routinely, which are one beyond the actual range that the server has.

On the server side, responses are built by the NRTMGenerator, which takes a serial_start_requested and optional serial_end_requested. From the RPSLDatabaseStatus, we query serial_oldest_journal and serial_newest_journal to determine serial_start_available and serial_end_available. In our case, serial_end_requested would always be None, i.e. LAST. Then there's a few tests and responses that may apply:

1. serial_start_requested < serial_start_available errors: Serials {serial_start_requested} - {serial_start_available} do not exist - you are querying older serials than are known.
   serial_end_available
2. serial_start_requested == serial_end_available + = warns: there are no newer updates available - you are querying just beyond the range.
3. serial_start_requested > serial_end_available errors: Serials {serial_end_available} - {serial_start_requested} do not exist - the serials you are querying are way newer than are known.

Log sample 1

2023-12-04 13:39:13,176 irrd[1188550]: [irrd.mirroring.mirror_runners_import#INFO] Retrieving NRTM updates for RADB from serial 255032 on nrtm.radb.net:43
2023-12-04 13:39:13,176 irrd[1188550]: [irrd.utils.whois_client#DEBUG] Running whois query -g RADB:3:255032-LAST on nrtm.radb.net port 43
2023-12-04 13:39:13,300 irrd[1188550]: [irrd.mirroring.mirror_runners_import#DEBUG] Received NRTM response for RADB: % Warning: there are no newer updates available

This is normal behaviour that suggests you are up to date.

Log sample 2

2023-12-04 13:54:14,507 irrd[1189565]: [irrd.mirroring.mirror_runners_import#INFO] Retrieving NRTM updates for RADB from serial 255032 on nrtm.radb.net:43
2023-12-04 13:54:14,508 irrd[1189565]: [irrd.utils.whois_client#DEBUG] Running whois query -g RADB:3:255032-LAST on nrtm.radb.net port 43
2023-12-04 13:54:14,622 irrd[1189565]: [irrd.mirroring.mirror_runners_import#DEBUG] Received NRTM response for RADB: %% ERROR: Serials 255032 - 268299 do not exist

This request and response are scenario 1: the remote journal starts at 268299, but you're asking for 255032. You are too far behind, it doesn't have the entries older than 268299. This is only recoverable with a full reload.

There are a few possible causes for this situation: your IRRD has been down for a while, the NRTMv3 server keeps only very short journals so the window is very narrow, or there has been a persistent issue before this which was preventing you from keeping up with NRTM. You'll have to dig more into your logs to figure out which, or perhaps RADB can tell us more about anything unusual on their end.

Other log samples

It is not possible to know what was happening there, as you need to know both the query and the response to figure out whether this is scenario 1 or 3.

[teunvink]

As one of the operators of IRRExplorer (which uses irrd as one of its backends) I can confirm that we've seen similar problems over the past months as well. We're currently running irrd 4.4.2.

[dhutchin-ctl]

Notice Log Sample 2 is exactly 15 minutes after Log Sample 1. There were no RADB updates on the client side between those two samples. So the first serial to request on the client side should not change. I don’t know where “268299” comes from. I will make myself available for you when ever you want to see more directly into the LEVEL3 system. I know, that doesn’t give you access to the RADB system at the same time. And of course, we don’t know how to trigger the error. I’m writing a script to more closely monitor the log so I will know shortly after this condition pops its head again. D

[schelcj]

We've seen the same internally and have been investigating as well. We saw the same serial constraint violation for the same serial as @dhutchin-ctl. Our nrtm.radb.net is fed via nrtm from the authoritative host and when this error hit any futher updates were blocked. A reseed resolved the issue but fairly certain we saw this once before after the v4 migration. We are also adding more monitoring and still investigating.

[mxsasha]

Notice Log Sample 2 is exactly 15 minutes after Log Sample 1. There were no RADB updates on the client side between those two samples. So the first serial to request on the client side should not change.

Ah right, that gives a bit more context. Using my earlier comment on NRTM responses and their precise meaning, we can narrow down.

We can assume the client keeps requesting 255032-LAST. At first, RADB replies:

2023-12-04 13:39:13,300 irrd[1188550]: [irrd.mirroring.mirror_runners_import#DEBUG] Received NRTM response for RADB: % Warning: there are no newer updates available

This is expected in a correctly running setup where you are up to date. This message means RADB has journal entries up to and including 255031, and you have those too in the mirror. All good.

15 minutes later, RADB replies:

2023-12-04 13:54:14,622 irrd[1189565]: [irrd.mirroring.mirror_runners_import#DEBUG] Received NRTM response for RADB: %% ERROR: Serials 255032 - 268299 do not exist

(The assumption that this is the same 255032-LAST query is consistent with the fact that the response mentions this serial. So we can be quite sure the same query was used both times.)

RADB now reports that its first serial is actually 268299 in the journal. That means it jumped 13267 serials in 15 minutes. 13K changes in 15 minutes is rare but not impossible, but what is strange here is that the journal did not just grow with at least 13K entries, the oldest 13K were also removed from the journal. It is impossible for clients to keep up in that case, or recover from that situation.

There are two scenarios I can think of:

• A high rate of changes combined with a very fast journal expiry.
• The queries are somehow arriving at different IRRD hosts that do not (all) have synchronised serials, which means their serials are somewhat near each other, but not the same.

[troy2914]

if I am reading your two scenarios properly, those are both things to address on the RADB side?

[schelcj]

For the serials jumping we have a maintainer whose automated processes may have gone sideways and producing a lot of unnecessary updates. We are reaching out to them to address.

[troy2914]

For the serials jumping we have a maintainer whose automated processes may have gone sideways and producing a lot of unnecessary updates. We are reaching out to them to address.

that sounds like a 4.4.3 request :) to add a limit/throttle.

[schelcj]

Back to the original issue; reviewing logs this morning shows that our nrtm.radb.net host retrieved, and applied, updates up to and shortly after 225031 then for unknown reasons tried to reapply that serial and ran into the unique key constraint preventing all further updates. We only had logging at INFO level so there isn't much more to go on at this time but have enabled DEBUG logging to review if this happens again.

2023-12-02 21:47:20,121 irrd[253050]: [irrd.mirroring.nrtm_operation#INFO] Completed NRTM operation RADB/255031/ADD/route6/2605:9CC0:397::/48AS8987
2023-12-02 21:47:20,122 irrd[253050]: [irrd.mirroring.nrtm_operation#INFO] Completed NRTM operation RADB/255032/ADD/route6/2605:9CC0:399::/48AS8987                                         
2023-12-02 21:47:20,123 irrd[253050]: [irrd.mirroring.nrtm_operation#INFO] Completed NRTM operation RADB/255033/ADD/route/130.137.120.0/24AS8987                                            
2023-12-02 21:47:20,135 irrd[253050]: [irrd.mirroring.mirror_runners_import#ERROR] An exception occurred while attempting a mirror update or initial import for RADB: (psycopg2.errors.Unique
DETAIL:  Key (serial_nrtm, source)=(255031, RADB) already exists.