search

NLnetLabs / routinator

An RPKI Validator and RTR server written in Rust
https://nlnetlabs.nl/projects/routing/routinator/
BSD 3-Clause "New" or "Revised" License
465 stars 70 forks source link

Odd reporting of VRP counts in syslog #659

Closed morrowc closed 3 years ago

morrowc commented 3 years ago

Howdy! On, at least, 0.10.2 I see what look like odd reports in log messages:

(clipped out from a salt-ssh command run across all instances deployed, a subset that shows the behavior)

emea-west-routinator-02:

retcode:
    0
stderr:
stdout:
    Oct  3 21:41:39 routinator-emea-west-02 routinator[19334]: Validation completed.
    Oct  3 21:41:39 routinator-emea-west-02 routinator[19334]: Summary at 2021-10-03 21:40:12.225649422 UTC
    Oct  3 21:41:39 routinator-emea-west-02 routinator[19334]: apnic: 17045 verified ROAs, 79601 verified VRPs, 0 unsafe VRPs, 79336 final VRPs.
    Oct  3 21:41:39 routinator-emea-west-02 routinator[19334]: arin: 17045 verified ROAs, 79601 verified VRPs, 0 unsafe VRPs, 0 final VRPs.
    Oct  3 21:41:39 routinator-emea-west-02 routinator[19334]: ripe: 25883 verified ROAs, 139408 verified VRPs, 0 unsafe VRPs, 139406 final VRPs.
    Oct  3 21:41:39 routinator-emea-west-02 routinator[19334]: lacnic: 9467 verified ROAs, 17858 verified VRPs, 0 unsafe VRPs, 16510 final VRPs.
    Oct  3 21:41:39 routinator-emea-west-02 routinator[19334]: afrinic: 2593 verified ROAs, 3409 verified VRPs, 0 unsafe VRPs, 3357 final VRPs.
    Oct  3 21:41:39 routinator-emea-west-02 routinator[19334]: total: 72033 verified ROAs, 319877 verified VRPs, 0 unsafe VRPs, 238609 final VRPs.
    Oct  3 21:41:39 routinator-emea-west-02 routinator[19334]: New serial is 36.

emea-west-routinator-01:

retcode:
    0
stderr:
stdout:
    Oct  3 21:43:57 routinator-emea-west-01 routinator[22365]: Validation completed.
    Oct  3 21:43:57 routinator-emea-west-01 routinator[22365]: Summary at 2021-10-03 21:42:37.659558940 UTC
    Oct  3 21:43:57 routinator-emea-west-01 routinator[22365]: apnic: 17045 verified ROAs, 79601 verified VRPs, 0 unsafe VRPs, 79336 final VRPs.
    Oct  3 21:43:57 routinator-emea-west-01 routinator[22365]: arin: 17045 verified ROAs, 79601 verified VRPs, 0 unsafe VRPs, 0 final VRPs.
    Oct  3 21:43:57 routinator-emea-west-01 routinator[22365]: ripe: 25883 verified ROAs, 139408 verified VRPs, 0 unsafe VRPs, 139406 final VRPs.
    Oct  3 21:43:57 routinator-emea-west-01 routinator[22365]: lacnic: 9467 verified ROAs, 17858 verified VRPs, 0 unsafe VRPs, 16510 final VRPs.
    Oct  3 21:43:57 routinator-emea-west-01 routinator[22365]: afrinic: 2593 verified ROAs, 3409 verified VRPs, 0 unsafe VRPs, 3357 final VRPs.
    Oct  3 21:43:57 routinator-emea-west-01 routinator[22365]: total: 72033 verified ROAs, 319877 verified VRPs, 0 unsafe VRPs, 238609 final VRPs.
    Oct  3 21:43:57 routinator-emea-west-01 routinator[22365]: New serial is 39.

emea-north-routinator-01:

retcode:
    0
stderr:
stdout:
    Oct  3 21:44:02 routinator-emea-north-01 routinator[20850]: Validation completed.
    Oct  3 21:44:02 routinator-emea-north-01 routinator[20850]: Summary at 2021-10-03 21:42:40.492964675 UTC
    Oct  3 21:44:02 routinator-emea-north-01 routinator[20850]: apnic: 17045 verified ROAs, 79601 verified VRPs, 0 unsafe VRPs, 79336 final VRPs.
    Oct  3 21:44:02 routinator-emea-north-01 routinator[20850]: arin: 17045 verified ROAs, 79601 verified VRPs, 0 unsafe VRPs, 0 final VRPs.
    Oct  3 21:44:02 routinator-emea-north-01 routinator[20850]: ripe: 25883 verified ROAs, 139408 verified VRPs, 0 unsafe VRPs, 139406 final VRPs.
    Oct  3 21:44:02 routinator-emea-north-01 routinator[20850]: lacnic: 9467 verified ROAs, 17858 verified VRPs, 0 unsafe VRPs, 16510 final VRPs.
    Oct  3 21:44:02 routinator-emea-north-01 routinator[20850]: afrinic: 2593 verified ROAs, 3409 verified VRPs, 0 unsafe VRPs, 3357 final VRPs.
    Oct  3 21:44:02 routinator-emea-north-01 routinator[20850]: total: 72033 verified ROAs, 319877 verified VRPs, 0 unsafe VRPs, 238609 final VRPs.
    Oct  3 21:44:02 routinator-emea-north-01 routinator[20850]: New serial is 39.

emea-north-routinator-02:

retcode:
    0
stderr:
stdout:
    Oct  3 21:44:33 routinator-emea-north-02 routinator[21193]: Validation completed.
    Oct  3 21:44:33 routinator-emea-north-02 routinator[21193]: Summary at 2021-10-03 21:43:08.185072725 UTC
    Oct  3 21:44:33 routinator-emea-north-02 routinator[21193]: apnic: 17045 verified ROAs, 79601 verified VRPs, 0 unsafe VRPs, 79336 final VRPs.
    Oct  3 21:44:33 routinator-emea-north-02 routinator[21193]: arin: 17045 verified ROAs, 79601 verified VRPs, 0 unsafe VRPs, 0 final VRPs.
    Oct  3 21:44:33 routinator-emea-north-02 routinator[21193]: ripe: 25883 verified ROAs, 139408 verified VRPs, 0 unsafe VRPs, 139406 final VRPs.
    Oct  3 21:44:33 routinator-emea-north-02 routinator[21193]: lacnic: 9467 verified ROAs, 17858 verified VRPs, 0 unsafe VRPs, 16510 final VRPs.
    Oct  3 21:44:33 routinator-emea-north-02 routinator[21193]: afrinic: 2593 verified ROAs, 3409 verified VRPs, 0 unsafe VRPs, 3357 final VRPs.
    Oct  3 21:44:33 routinator-emea-north-02 routinator[21193]: total: 72033 verified ROAs, 319877 verified VRPs, 0 unsafe VRPs, 238609 final VRPs.
    Oct  3 21:44:33 routinator-emea-north-02 routinator[21193]: New serial is 35.

asia-east-routinator-02:

retcode:
    0
stderr:
stdout:
    Oct  3 21:45:38 asia-east-routinator-02 routinator[19410]: Validation completed.
    Oct  3 21:45:38 asia-east-routinator-02 routinator[19410]: Summary at 2021-10-03 21:44:09.346249835 UTC
    Oct  3 21:45:38 asia-east-routinator-02 routinator[19410]: afrinic: 2593 verified ROAs, 3409 verified VRPs, 0 unsafe VRPs, 3357 final VRPs.
    Oct  3 21:45:38 asia-east-routinator-02 routinator[19410]: lacnic: 9467 verified ROAs, 17858 verified VRPs, 0 unsafe VRPs, 16510 final VRPs.
    Oct  3 21:45:38 asia-east-routinator-02 routinator[19410]: arin: 17045 verified ROAs, 79601 verified VRPs, 0 unsafe VRPs, 79336 final VRPs.
    Oct  3 21:45:38 asia-east-routinator-02 routinator[19410]: ripe: 25883 verified ROAs, 139408 verified VRPs, 0 unsafe VRPs, 139406 final VRPs.
    Oct  3 21:45:38 asia-east-routinator-02 routinator[19410]: apnic: 17045 verified ROAs, 79601 verified VRPs, 0 unsafe VRPs, 0 final VRPs.
    Oct  3 21:45:38 asia-east-routinator-02 routinator[19410]: total: 72033 verified ROAs, 319877 verified VRPs, 0 unsafe VRPs, 238609 final VRPs.
    Oct  3 21:45:38 asia-east-routinator-02 routinator[19410]: New serial is 35.

What's interesting are lines like: routinator[19410]: apnic: 17045 verified ROAs, 79601 verified VRPs, 0 unsafe VRPs, 0 final VRPs. routinator[21193]: arin: 17045 verified ROAs, 79601 verified VRPs, 0 unsafe VRPs, 0 final VRPs.

It looks like we MOSTLY get the 2nd line(arin 0 final vrps) in logs currently, with 1 exception being the 1st line (apnic 0 final vrps). The interesting other tidbit is that the total lines all appear to agree across the deployment: total: 72033 verified ROAs, 319877 verified VRPs, 0 unsafe VRPs, 238609 final VRPs.

I think this is just 'logged incorrectly' data, and not a real problem... but it's curious :) and is causing us some confusion :) Happy to provide logs/etc or other bits if that'll help. I'll also go looking at the code to see if I can divine where it might cross streams/etc.

partim commented 3 years ago

The identical numbers for raw ROAs for ARIN and APNIC makes it look suspiciously like you are somehow using the APNIC TAL as your ARIN TAL. Our own instance is currently reporting:

valid-roas-per-tal: apnic=17064 ripe=25881 arin=37401 lacnic=9468 afrinic=2599
morrowc commented 3 years ago

100% I could be 'holding it wrong', but the tals are placed in a directory: /srv/rpki/rpki-cache/tals

$ ls -l /srv/rpki/rpki-cache/tals/ total 20 -rw-r--r-- 1 morrowc morrowc 448 Aug 20 2019 afrinic.tal -rw-r--r-- 1 morrowc morrowc 466 Aug 20 2019 apnic.tal -rw-r--r-- 1 morrowc morrowc 466 May 27 05:01 arin.tal -rw-r--r-- 1 morrowc morrowc 462 Aug 20 2019 lacnic.tal -rw-r--r-- 1 morrowc morrowc 441 Aug 20 2019 ripe.tal

oh, good lord :( wtf :( $ cat /srv/rpki/rpki-cache/tals/arin.tal rsync://rpki.apnic.net/repository/apnic-rpki-root-iana-origin.cer

MIIBIjANBgkqhkiG9w0BAQEFAAOCAQ8AMIIBCgKCAQEAx9RWSL61YAAYumEiU8z8 .....

process runs as such: /usr/local/bin/routinator -b /srv/rpki -t /srv/rpki/rpki-cache/tals -r /srv/rpki/rpki-cache -v --syslog --syslog-facility=local7 --logfile /var/log/routinator.log server --http=127.0.0.1:9090 --pid-file=/srv/rpki/routinator.pid --working-dir /srv/rpki -d

ok, fine. this is almost certainly a 'management of the file contents' fail :(

morrowc commented 3 years ago

to make sure this is closed with correcting info: 1) yes, the arin.tal file had apnic data (I have no story for how that happened, except I made a mistake) 2) when corrected: Oct 4 19:55:05 routinator-asia-east-01 routinator[27902]: Validation completed. Oct 4 19:55:05 routinator-asia-east-01 routinator[27902]: Summary at 2021-10-04 19:41:29.948713408 UTC Oct 4 19:55:05 routinator-asia-east-01 routinator[27902]: apnic: 17071 verified ROAs, 79665 verified VRPs, 0 unsafe VRPs, 79400 final VRPs. Oct 4 19:55:05 routinator-asia-east-01 routinator[27902]: arin: 37415 verified ROAs, 45176 verified VRPs, 1 unsafe VRPs, 42295 final VRPs. Oct 4 19:55:05 routinator-asia-east-01 routinator[27902]: ripe: 25887 verified ROAs, 139474 verified VRPs, 17 unsafe VRPs, 139472 final VRPs. Oct 4 19:55:05 routinator-asia-east-01 routinator[27902]: lacnic: 9501 verified ROAs, 17895 verified VRPs, 0 unsafe VRPs, 16547 final VRPs. Oct 4 19:55:05 routinator-asia-east-01 routinator[27902]: afrinic: 2601 verified ROAs, 3417 verified VRPs, 0 unsafe VRPs, 3365 final VRPs. Oct 4 19:55:05 routinator-asia-east-01 routinator[27902]: total: 92475 verified ROAs, 285627 verified VRPs, 18 unsafe VRPs, 281079 final VRPs. Oct 4 19:55:05 routinator-asia-east-01 routinator[27902]: New serial is 0.

thanks! (for pointing out: "you are holding it wrong") :)