More validation debugging information could be useful

[job]

There is an ongoing issue with the ARIN RPKI Trust Anchor https://www.arin.net/announcements/20200812/

The issue is explained in greater detail here http://sobornost.net/~job/arin-manifest-issue-2020.08.12.txt

In this situation rpki-client gives the following error:

job@bench ~$ doas rpki-client -n -v -t /etc/rpki/arin.tal
rpki-client: rpki.arin.net/repository: pulling from network
rpki-client: rpki.arin.net/repository: loaded from cache
rpki-client: rpki.arin.net/repository/arin-rpki-ta/5e4a23ea-e80a-403e-b08c-2171da2157d3/5e4a23ea-e80a-403e-b08c-2171da2157d3.mft: certificate signature failure
rpki-client: all files parsed: generating output
rpki-client: Route Origin Authorizations: 0 (0 failed parse, 0 invalid)
rpki-client: Certificates: 2 (0 failed parse, 0 invalid)
rpki-client: Trust Anchor Locators: 1
rpki-client: Manifests: 2 (1 failed parse, 0 stale)
rpki-client: Certificate revocation lists: 1
rpki-client: Repositories: 1
rpki-client: Files removed: 0
rpki-client: VRP Entries: 0 (0 unique)

However, when running FORT, the below output gives very little to go on, I think operators would benefit from more insight into why the tree is not validating. (I believe FORT behaves correctly, just doesn't provide much debug info)

$ fort --tal=/etc/rpki/arin.tal --rrdp.enabled=true --output.roa=- --mode=standalone --log.output=console --log.level=debug --log.enabled=true
Aug 13 12:03:54 INF: Disabling validation logging on syslog.
Aug 13 12:03:54 INF: Disabling validation logging on standard streams.
Aug 13 12:03:54 INF: Console log output configured; disabling operation logging on syslog.
Aug 13 12:03:54 INF: (Operation Logs will be sent to the standard streams only.)
Aug 13 12:03:54 INF: Configuration {
Aug 13 12:03:54 INF: tal: /etc/rpki/arin.tal
Aug 13 12:03:54 INF: local-repository: /tmp/fort/repository
Aug 13 12:03:54 INF: sync-strategy: root-except-ta
Aug 13 12:03:54 INF: shuffle-uris: false
Aug 13 12:03:54 INF: maximum-certificate-depth: 32
Aug 13 12:03:54 INF: slurm: (null)
Aug 13 12:03:54 INF: mode: standalone
Aug 13 12:03:54 INF: work-offline: false
Aug 13 12:03:54 INF: server.address: (null)
Aug 13 12:03:54 INF: server.port: 323
Aug 13 12:03:54 INF: server.backlog: 128
Aug 13 12:03:54 INF: server.interval.validation: 3600
Aug 13 12:03:54 INF: server.interval.refresh: 3600
Aug 13 12:03:54 INF: server.interval.retry: 600
Aug 13 12:03:54 INF: server.interval.expire: 7200
Aug 13 12:03:54 INF: rsync.enabled: true
Aug 13 12:03:54 INF: rsync.priority: 50
Aug 13 12:03:54 INF: rsync.strategy: root-except-ta
Aug 13 12:03:54 INF: rsync.retry.count: 2
Aug 13 12:03:54 INF: rsync.retry.interval: 5
Aug 13 12:03:54 INF: rsync.program: rsync
Aug 13 12:03:54 INF: rsync.arguments-recursive:
Aug 13 12:03:54 INF:   --recursive
Aug 13 12:03:54 INF:   --delete
Aug 13 12:03:54 INF:   --times
Aug 13 12:03:54 INF:   --contimeout=20
Aug 13 12:03:54 INF:   --timeout=15
Aug 13 12:03:54 INF:   $REMOTE
Aug 13 12:03:54 INF:   $LOCAL
Aug 13 12:03:54 INF: rsync.arguments-flat:
Aug 13 12:03:54 INF:   --times
Aug 13 12:03:54 INF:   --contimeout=20
Aug 13 12:03:54 INF:   --timeout=15
Aug 13 12:03:54 INF:   --dirs
Aug 13 12:03:54 INF:   $REMOTE
Aug 13 12:03:54 INF:   $LOCAL
Aug 13 12:03:54 INF: rrdp.enabled: true
Aug 13 12:03:54 INF: rrdp.priority: 50
Aug 13 12:03:54 INF: rrdp.retry.count: 2
Aug 13 12:03:54 INF: rrdp.retry.interval: 5
Aug 13 12:03:54 INF: http.user-agent: fort/1.3.0
Aug 13 12:03:54 INF: http.connect-timeout: 30
Aug 13 12:03:54 INF: http.transfer-timeout: 0
Aug 13 12:03:54 INF: http.idle-timeout: 15
Aug 13 12:03:54 INF: http.ca-path: (null)
Aug 13 12:03:54 INF: log.enabled: true
Aug 13 12:03:54 INF: log.output: console
Aug 13 12:03:54 INF: log.level: debug
Aug 13 12:03:54 INF: log.tag: (null)
Aug 13 12:03:54 INF: log.facility: daemon
Aug 13 12:03:54 INF: log.file-name-format: global-url
Aug 13 12:03:54 INF: log.color-output: false
Aug 13 12:03:54 INF: validation-log.enabled: false
Aug 13 12:03:54 INF: validation-log.output: console
Aug 13 12:03:54 INF: validation-log.level: warning
Aug 13 12:03:54 INF: validation-log.tag: Validation
Aug 13 12:03:54 INF: validation-log.facility: daemon
Aug 13 12:03:54 INF: validation-log.file-name-format: global-url
Aug 13 12:03:54 INF: validation-log.color-output: false
Aug 13 12:03:54 INF: Custom incidences:
Aug 13 12:03:54 INF:   incid-hashalg-has-params (Signed Object's hash algorithm has NULL object as parameters): ignore
Aug 13 12:03:54 INF:   incid-obj-not-der-encoded (Object isn't DER encoded): ignore
Aug 13 12:03:54 INF:   incid-file-at-mft-not-found (File listed at manifest doesn't exist): error
Aug 13 12:03:54 INF:   incid-file-at-mft-hash-not-match (File hash listed at manifest doesn't match the actual file hash): error
Aug 13 12:03:54 INF: output.roa: -
Aug 13 12:03:54 INF: output.bgpsec: (null)
Aug 13 12:03:54 INF: asn1-decode-max-stack: 4096
Aug 13 12:03:54 INF: stale-repository-period: 43200
Aug 13 12:03:54 INF: }
Aug 13 12:03:54 DBG: rpkiManifest registered. Its nid is 1001.
Aug 13 12:03:54 DBG: signedObject registered. Its nid is 1002.
Aug 13 12:03:54 DBG: rpkiNotify registered. Its nid is 1003.
Aug 13 12:03:54 DBG: id-cp-ipAddr-asNumber (RFC 6484) registered. Its nid is 1004.
Aug 13 12:03:54 DBG: id-cp-ipAddr-asNumber-v2 (RFC 8360) registered. Its nid is 1005.
Aug 13 12:03:54 DBG: id-pe-ipAddrBlocks-v2 registered. Its nid is 1006.
Aug 13 12:03:54 DBG: id-pe-autonomousSysIds-v2 registered. Its nid is 1007.
Aug 13 12:03:54 DBG: id-kp-bgpsec-router registered. Its nid is 1008.
Aug 13 12:03:54 INF: Starting validation.
ASN,Prefix,Max prefix length
Aug 13 12:04:14 INF: Validation finished:
Aug 13 12:04:14 INF: - Valid Prefixes: 0
Aug 13 12:04:14 INF: - Valid Router Keys: 0
Aug 13 12:04:14 INF: - Real execution time: 20 secs.

[pcarana]

Hi Job!

This happens due to a recent update. Currently there are 2 types of logs: the operation logs (enabled by default) and the validation logs (disabled by default). To learn more about them, visit https://nicmx.github.io/FORT-validator/logging.html.

Before v1.3.0 all the logs where "sent" to the same configured output. This caused some confusion amongst operators since apparently they believed they had done something wrong, even when that was not the case (several warnings were shown, all of them regarding RPKI objects validation).

So, as of today, you could use --validation-log.enabled to get all the messages regarding RPKI objects validation (by default it has a 'warning' level).

[job]

Fantastic!

this is good output

job@vurt ~$ fort --validation-log.enabled --tal=/etc/rpki/arin.tal --rrdp.enabled=true --output.roa=- --mode=standalone --log.output=console --log.level=debug --log.enabled
Aug 13 14:22:58 ERR [Validation]: rsync://rpki.arin.net/repository/arin-rpki-ta/5e4a23ea-e80a-403e-b08c-2171da2157d3/5e4a23ea-e80a-403e-b08c-2171da2157d3.mft: Certificate validation failed: certificate signature failure
Aug 13 14:23:05 ERR [Validation]: rsync://rpki.arin.net/repository/arin-rpki-ta/5e4a23ea-e80a-403e-b08c-2171da2157d3/5e4a23ea-e80a-403e-b08c-2171da2157d3.mft: Certificate validation failed: certificate signature failure

[pcarana]

Glad to help! :smiley: