missing some NRTM data?

[job]

Unsure what happened here, an NRTM update came in:

2019-02-01 09:53:37,109 irrd[27482]: [irrd.mirroring.nrtm_operation#INFO] Completed NRTM operation RIPE/43672782/ADD/185.21.225.0/24AS42442

IRRd v2 picked it up:

hanna:~ job$ whois -h rr.ntt.net 185.21.225.0/24
route:          185.21.225.0/24
origin:         AS42442
mnt-by:         MNT-STRAYLIGHT
created:        2019-02-01T09:52:52Z
last-modified:  2019-02-01T09:52:52Z
source:         RIPE
remarks:        ****************************
remarks:        * THIS OBJECT IS MODIFIED
remarks:        * Please note that all data that is generally regarded as personal
remarks:        * data has been removed from this object.
remarks:        * To view the original object, please query the RIPE Database at:
remarks:        * http://www.ripe.net/whois
remarks:        ****************************

But IRRd v4 still shows only the overlapping route object, and the /24 from above is missing.

hanna:~ job$ whois -h irrd01.ip.gin.ntt.net 185.21.225.0/24
route:          185.21.224.0/23
descr:          Straylight UG
origin:         AS60683
mnt-by:         MNT-STRAYLIGHT
created:        2013-12-19T09:43:16Z
last-modified:  2013-12-19T09:43:16Z
source:         RIPE
remarks:        ****************************
remarks:        * THIS OBJECT IS MODIFIED
remarks:        * Please note that all data that is generally regarded as personal
remarks:        * data has been removed from this object.
remarks:        * To view the original object, please query the RIPE Database at:
remarks:        * http://www.ripe.net/whois
remarks:        ****************************

[troy2914]

not showing in rpsl_objects:

select * from rpsl_objects where rpsl_pk = '185.21.225.0/24S42442';
 pk | rpsl_pk | source | object_class | parsed_data | object_text | ip_version | ip_first | ip_last | ip_size | asn_first | asn_last | created | updated
----+---------+--------+--------------+-------------+-------------+------------+----------+---------+---------+-----------+----------+---------+---------
(0 rows)

btw, 185.21.224.0/24 seems to be missing too. though a 194.151.0.0/17 which came in 5 minutes later is present.

[troy2914]

just looking at diffs, and noticed this nrtm change:

2019-01-31 14:35:39,888 irrd[53224]: [irrd.mirroring.nrtm_operation#INFO] Completed NRTM operation APNIC/7003593/DEL/103.90.84.0/22AS18222
2019-01-31 14:35:39,900 irrd[53224]: [irrd.mirroring.nrtm_operation#INFO] Completed NRTM operation APNIC/7003600/ADD/103.90.84.0/22AS23647

but querying irrd4 shows the old origin:

whois -h localhost 103.90.84.0/22
route:          103.90.84.0/22
origin:         AS18222
descr:          Data Hub Pvt. Ltd.
            2nd Floor, Shikhar Biz Center, Thapathali
mnt-by:         MAINT-DATAHUB-NP
last-modified:  2018-11-29T10:52:15Z
source:         APNIC

expected to see:

route:          103.90.84.0/22
origin:         AS23647
descr:          Data Hub Pvt. Ltd.
            2nd Floor, Shikhar Biz Center, Thapathali
mnt-by:         MAINT-DATAHUB-NP
last-modified:  2019-01-31T14:33:14Z
source:         APNIC

[mxsasha]

Assuming we're still logging all SQL queries, I need the full postgresql logs from the 10 minutes or so surrounding all of the failed updates. I don't have access to the logs myself.

These updates have been successfully processed in my local install. I'll do some more digging in the database too.

[job]

@mxsasha you should now be able to read /var/log/postgresql files on irrd01.ip.gin.ntt.net, the data is somewhere in postgresql-9.6-main.log.1

[mxsasha]

Working from the RIPE update, the NRTM update had a serial of 43672782, and seems to have been inserted into the database correctly:

2019-02-01 09:53:37.113 UTC [27705] irrd@irrd LOG:  duration: 0.180 ms  statement: INSERT INTO rpsl_database_journal (rpsl_pk, source, serial_nrtm, operation, object_class, object_text) VALUES ('185.21.225.0/24AS42442', 'RIPE', 43672782, 'add_or_update', 'route', 'route:          185.21.225.0/24
        origin:         AS42442
        mnt-by:         MNT-STRAYLIGHT
        created:        2019-02-01T09:52:52Z
        last-modified:  2019-02-01T09:52:52Z
        source:         RIPE
        remarks:        ****************************
        remarks:        * THIS OBJECT IS MODIFIED
        remarks:        * Please note that all data that is generally regarded as personal
        remarks:        * data has been removed from this object.
        remarks:        * To view the original object, please query the RIPE Database at:
        remarks:        * http://www.ripe.net/whois
        remarks:        ****************************

This seems to match with the expected object, so the NRTM update was correctly processed. A query slightly before this updated rpsl_objects. However, these entries were deleted, because a few hours later:

2019-02-01 14:22:40.841 UTC [67707] irrd@irrd LOG:  duration: 50877.642 ms  statement: DELETE FROM rpsl_objects WHERE rpsl_objects.source = 'RIPE'
2019-02-01 14:22:42.866 UTC [67707] irrd@irrd LOG:  duration: 2007.589 ms  statement: DELETE FROM rpsl_database_journal WHERE rpsl_database_journal.source = 'RIPE'

It seems IRRd was restarted around that time, with force_reload set for most or all sources. We reloaded at serial 43668026 (4756 earlier than the ADD for 185.21.225.0/24AS2442):

2019-02-01 14:21:49,904 irrd[67696]: [irrd.mirroring.mirror_runners_import#INFO] Downloaded ftp://ftp.ripe.net/ripe/dbase/RIPE.CURRENTSERIAL, contained 43668026
2019-02-01 15:56:49,083 irrd[67696]: [irrd.mirroring.parsers#INFO] File import for RIPE: 6581154 objects read, 439801 objects inserted, ignored 36 due to errors, ignored 6015078 due to object_class_filter, serial 43668026, source /tmp/tmpb81kl97i
2019-02-01 15:56:49,083 irrd[67696]: [irrd.mirroring.parsers#WARNING] Ignored 126239 objects found in file import for RIPE due to unknown object classes: *xx-num, poem, ipv6-site, limerick, poetic-form, *xxte6, *xxner, *xxte-set, irt, *xxson, *xxe, organisation, *xxset, *xxte

However, the first NRTM update retrieval used a serial that was 7715 higher than CURRENTSERIAL of the dump:

2019-02-01 15:57:03,173 irrd[67696]: [irrd.mirroring.mirror_runners_import#INFO] Retrieving NRTM updates for RIPE from serial 43675741 on 193.0.6.135:4444

The 185.21.225.0/24AS42442 update was not in the dump, and was skipped over when retrieving NRTM updates. A similar scenario happened for the two APNIC updates. The issue is that serial_newest_seen is not reset between full reloads, which will be fixed.

[mxsasha]

Note that another forced full reload is required to correct the data.