[RPKI] "Permission denied (13)" rsync errors

Tue Mar 3 16:27:54 UTC 2020

I'm still seeing what I think are a lot of errors but I don't know if these are okay and everyone else is seeing the same errors or if it's just me.  Here is an example of what I'm seeing in syslog:
[rcompton at rpki-validator3 ~]$ sudo grep routinator /var/log/messages | tail -50
Mar  3 16:12:41 rpki-validator3 routinator: rsync://rpki.cnnic.cn/rpki/A9162E3D0000/721/GglYCbitgZHiv1DP4TSiiZp0O1k.roa not found in its RRDP repository.
Mar  3 16:12:41 rpki-validator3 routinator: rsync://rpki.cnnic.cn/rpki/A9162E3D0000/721/GglYCbitgZHiv1DP4TSiiZp0O1k.roa: failed to load.
Mar  3 16:12:41 rpki-validator3 routinator: rsync://rpki.cnnic.cn/rpki/A9162E3D0000/721/HPIsJIsEXp8sFR9To7lpgytOO_8.roa not found in its RRDP repository.
Mar  3 16:12:41 rpki-validator3 routinator: rsync://rpki.cnnic.cn/rpki/A9162E3D0000/721/HPIsJIsEXp8sFR9To7lpgytOO_8.roa: failed to load.
Mar  3 16:12:41 rpki-validator3 routinator: rsync://rpki.cnnic.cn/rpki/A9162E3D0000/721/hnmO2s4a0uPBYGc04OQShbGvJ6c.roa not found in its RRDP repository.
Mar  3 16:12:41 rpki-validator3 routinator: rsync://rpki.cnnic.cn/rpki/A9162E3D0000/721/hnmO2s4a0uPBYGc04OQShbGvJ6c.roa: failed to load.
Mar  3 16:12:41 rpki-validator3 routinator: rsync://rpki.cnnic.cn/rpki/A9162E3D0000/2698/rHgoV8D3m679K26JUWBfGqJN79E.roa: processing failed.
Mar  3 16:12:41 rpki-validator3 routinator: RRDP https://rpki-ca.idnic.net/rrdp/notification.xml: Updating server
Mar  3 16:12:41 rpki-validator3 routinator: RRDP https://rrdp.rpki.nlnetlabs.nl/rrdp/notification.xml: Updating server
Mar  3 16:12:42 rpki-validator3 routinator: Serials: us 281, them 281
Mar  3 16:12:42 rpki-validator3 routinator: RRDP https://rpki-ca.idnic.net/rrdp/notification.xml: Delta update succeeded.
Mar  3 16:12:42 rpki-validator3 routinator: Serials: us 137, them 137
Mar  3 16:12:42 rpki-validator3 routinator: RRDP https://rrdp.rpki.nlnetlabs.nl/rrdp/notification.xml: Delta update succeeded.
Mar  3 16:12:42 rpki-validator3 routinator: rsyncing from rsync://rpki.arin.net/repository/.
Mar  3 16:12:42 rpki-validator3 routinator: rsync://rpki.arin.net/repository: Running command "rsync" "--contimeout=10" "--timeout=300" "-rltz" "--delete" "rsync://rpki.arin.net/repository/" "/home/rcompton/.rpki-cache/repository/rsync/rpki.arin.net/repository/"
Mar  3 16:12:42 rpki-validator3 routinator: rsync://rpki.arin.net/repository: failed with status exit code: 10
Mar  3 16:12:42 rpki-validator3 routinator: rsync://rpki.arin.net/repository: rsync: failed to connect to rpki.arin.net (2001:500:13::150): Permission denied (13)
Mar  3 16:12:42 rpki-validator3 routinator: rsync://rpki.arin.net/repository: rsync: failed to connect to rpki.arin.net (2001:500:a9::150): Permission denied (13)
Mar  3 16:12:42 rpki-validator3 routinator: rsync://rpki.arin.net/repository: rsync: failed to connect to rpki.arin.net (2001:500:31::150): Permission denied (13)
Mar  3 16:12:42 rpki-validator3 routinator: rsync://rpki.arin.net/repository: rsync: failed to connect to rpki.arin.net (199.71.0.150): Permission denied (13)
Mar  3 16:12:42 rpki-validator3 routinator: rsync://rpki.arin.net/repository: rsync: failed to connect to rpki.arin.net (199.5.26.150): Permission denied (13)
Mar  3 16:12:42 rpki-validator3 routinator: rsync://rpki.arin.net/repository: rsync: failed to connect to rpki.arin.net (199.212.0.150): Permission denied (13)
Mar  3 16:12:42 rpki-validator3 routinator: rsync://rpki.arin.net/repository: rsync error: error in socket IO (code 10) at clientserver.c(125) [Receiver=3.1.2]
Mar  3 16:12:42 rpki-validator3 routinator: Found valid trust anchor rsync://rpki.arin.net/repository/arin-rpki-ta.cer. Processing.
Mar  3 16:12:42 rpki-validator3 routinator: RRDP https://rrdp.arin.net/notification.xml: Updating server
Mar  3 16:12:42 rpki-validator3 routinator: RRDP https://rrdp.twnic.tw/rrdp/notify.xml: Updating server
Mar  3 16:12:42 rpki-validator3 routinator: Serials: us 2615, them 2616
Mar  3 16:12:43 rpki-validator3 routinator: RRDP https://rrdp.arin.net/notification.xml: Delta update succeeded.
Mar  3 16:12:43 rpki-validator3 routinator: Serials: us 864286, them 864332
Mar  3 16:12:44 rpki-validator3 routinator: RRDP https://rpki.tools.westconnect.ca/rrdp/notification.xml: Updating server
Mar  3 16:12:44 rpki-validator3 routinator: Serials: us 63, them 63
Mar  3 16:12:44 rpki-validator3 routinator: RRDP https://rpki.tools.westconnect.ca/rrdp/notification.xml: Delta update succeeded.
Mar  3 16:12:44 rpki-validator3 routinator: rsync://rpki.qs.nu/repo/qsnu/0/295C4D3D4242CB0AAA51BFA3A2CE5009238FF0FE.mft: stale manifest
Mar  3 16:12:44 rpki-validator3 routinator: rsync://rpki.qs.nu/repo/qsnu/0/295C4D3D4242CB0AAA51BFA3A2CE5009238FF0FE.crl: stale CRL.
Mar  3 16:12:52 rpki-validator3 routinator: RRDP https://rrdp.twnic.tw/rrdp/notify.xml: Delta update succeeded.
Mar  3 16:12:53 rpki-validator3 routinator: rsyncing from rsync://rpki-repository.nic.ad.jp/ap/.
Mar  3 16:12:53 rpki-validator3 routinator: rsync://rpki-repository.nic.ad.jp/ap: Running command "rsync" "--contimeout=10" "--timeout=300" "-rltz" "--delete" "rsync://rpki-repository.nic.ad.jp/ap/" "/home/rcompton/.rpki-cache/repository/rsync/rpki-repository.nic.ad.jp/ap/"
Mar  3 16:12:53 rpki-validator3 routinator: rsync://rpki-repository.nic.ad.jp/ap: failed with status exit code: 10
Mar  3 16:12:53 rpki-validator3 routinator: rsync://rpki-repository.nic.ad.jp/ap: rsync: failed to connect to rpki-repository.nic.ad.jp (192.41.192.216): Permission denied (13)
Mar  3 16:12:53 rpki-validator3 routinator: rsync://rpki-repository.nic.ad.jp/ap: rsync error: error in socket IO (code 10) at clientserver.c(125) [Receiver=3.1.2]
Mar  3 16:12:53 rpki-validator3 routinator: rsync://rpki.cnnic.cn/rpki/A9162E3D0000/423/Qz0qaGQsQRaH3wYRKwQ5iTO0s2U.mft not found in its RRDP repository.
Mar  3 16:12:53 rpki-validator3 routinator: rsync://rpki.cnnic.cn/rpki/A9162E3D0000/423/Qz0qaGQsQRaH3wYRKwQ5iTO0s2U.mft: failed to load.
Mar  3 16:12:53 rpki-validator3 routinator: rsync://rpki.cnnic.cn/rpki/A9162E3D0000/73/ceys1MCb3uAH_jR3TY6isl37R-E.mft not found in its RRDP repository.
Mar  3 16:12:53 rpki-validator3 routinator: rsync://rpki.cnnic.cn/rpki/A9162E3D0000/73/ceys1MCb3uAH_jR3TY6isl37R-E.mft: failed to load.
Mar  3 16:12:53 rpki-validator3 routinator: rsync://rpki.cnnic.cn/rpki/A9162E3D0000/643/qJA1jmKf5WZb7_gCt8DJUDRWzIg.mft not found in its RRDP repository.
Mar  3 16:12:53 rpki-validator3 routinator: rsync://rpki.cnnic.cn/rpki/A9162E3D0000/643/qJA1jmKf5WZb7_gCt8DJUDRWzIg.mft: failed to load.
Mar  3 16:12:53 rpki-validator3 routinator: rsync://rpki.cnnic.cn/rpki/A9162E3D0000/510/wQPfjZQWQRXjU8phfPVJC44D8n8.mft not found in its RRDP repository.
Mar  3 16:12:53 rpki-validator3 routinator: rsync://rpki.cnnic.cn/rpki/A9162E3D0000/510/wQPfjZQWQRXjU8phfPVJC44D8n8.mft: failed to load.
Mar  3 16:12:53 rpki-validator3 routinator: Diff with 0 announced and 0 withdrawn.
Mar  3 16:12:53 rpki-validator3 routinator: Validation completed. New serial is 34.

Also, my routers seem to be getting records:
admin at ENWECORZB0J-BCR04> show validation session 
Session                                  State   Flaps     Uptime #IPv4/IPv6 records
172.16.47.235                            Up          3   10:56:50 113286/19124

And the '/metrics' page seems to indicate that things are working:
[rcompton at rpki-validator3 ~]$ lynx http://127.0.0.1:8080/metrics
                                                                                                                                                                                                 (p1 of 3)
# HELP routinator_valid_roas number of valid ROAs seen
# TYPE routinator_valid_roas gauge
routinator_valid_roas{tal="afrinic"} 588
routinator_valid_roas{tal="lacnic"} 3292
routinator_valid_roas{tal="ripe"} 14300
routinator_valid_roas{tal="arin"} 6365
routinator_valid_roas{tal="apnic"} 6089

# HELP routinator_vrps_total total number of VRPs seen
# TYPE routinator_vrps_total gauge
routinator_vrps_total{tal="afrinic"} 1016
routinator_vrps_total{tal="lacnic"} 8836
routinator_vrps_total{tal="ripe"} 78817
routinator_vrps_total{tal="arin"} 9011
routinator_vrps_total{tal="apnic"} 35737

# HELP routinator_last_update_start seconds since last update started
# TYPE routinator_last_update_start gauge
routinator_last_update_start 180

# HELP routinator_last_update_duration duration in seconds of last update
# TYPE routinator_last_update_duration gauge
routinator_last_update_duration 19

# HELP routinator_last_update_done seconds since last update finished
# TYPE routinator_last_update_done gauge
routinator_last_update_done 160

# HELP routinator_serial current RTR serial number
# TYPE routinator_serial gauge
routinator_serial 34

# HELP routinator_rsync_status exit status of rsync command
# TYPE routinator_rsync_status gauge
routinator_rsync_status{uri="rsync://rpki.afrinic.net/repository/"} 10
routinator_rsync_status{uri="rsync://rpki.apnic.net/repository/"} 10
routinator_rsync_status{uri="rsync://repository.lacnic.net/rpki/"} 10
routinator_rsync_status{uri="rsync://rpki-repo.registro.br/repo/"} 10
routinator_rsync_status{uri="rsync://rpki.ripe.net/ta/"} 10
routinator_rsync_status{uri="rsync://rpkica.mckay.com/rpki/"} 10
routinator_rsync_status{uri="rsync://rpki.arin.net/repository/"} 10
routinator_rsync_status{uri="rsync://rpki-repository.nic.ad.jp/ap/"} 10

On 3/3/20, 7:13 AM, "Tim Bruijnzeels" <tim at nlnetlabs.nl> wrote:

    Hi,

    Sorry for the late reply.

    This looks like a temporary issue on the side of the lacnic repository server. Are you still seeing issues?

    Tim

    > On 28 Feb 2020, at 18:27, Compton, Rich A via RPKI <rpki at lists.nlnetlabs.nl> wrote:
    > 
    > Hi, I am trying to run routinator on a Centos7 VM. I created a systemd startup script and I'm running routinator at boot with it. I am getting "Permission denied (13)" errors on rsync. Also, the /metrics URL keeps saying "Initial validation ongoing. Please wait."
    > I'm getting some different errors if I just start routinator from the command line (see below). When I start routinator this way, the /metrics URL shows stats so I'm assume it's working.
    > 
    > Errors if I start routinator with the systemd script:
    > Feb 28 15:42:41 rpki-validator3 routinator: rsync://repository.lacnic.net/rpki: rsync: failed to connect to repository.lacnic.net (2001:13c7:7002:4128::137): Permission denied (13)
    > Feb 28 15:42:41 rpki-validator3 routinator: rsync://repository.lacnic.net/rpki: rsync: failed to connect to repository.lacnic.net (2001:13c7:7002:4128::185): Permission denied (13)
    > Feb 28 15:42:41 rpki-validator3 routinator: rsync://repository.lacnic.net/rpki: rsync: failed to connect to repository.lacnic.net (2001:13c7:7002:4128::136): Permission denied (13)
    > Feb 28 15:42:41 rpki-validator3 routinator: rsync://repository.lacnic.net/rpki: rsync: failed to connect to repository.lacnic.net (200.3.14.137): Permission denied (13)
    > Feb 28 15:42:41 rpki-validator3 routinator: rsync://repository.lacnic.net/rpki: rsync: failed to connect to repository.lacnic.net (200.3.14.185): Permission denied (13)
    > Feb 28 15:42:41 rpki-validator3 routinator: rsync://repository.lacnic.net/rpki: rsync: failed to connect to repository.lacnic.net (200.3.14.136): Permission denied (13)
    > Feb 28 15:42:41 rpki-validator3 routinator: rsync://repository.lacnic.net/rpki: rsync error: error in socket IO (code 10) at clientserver.c(125) [Receiver=3.1.2]
    > Feb 28 15:42:41 rpki-validator3 routinator: rsync://rpki.arin.net/repository: failed with status exit code: 10
    > 
    > Errors when I start routinator from the command line:
    > Feb 28 16:54:16 rpki-validator3 routinator[2128]: rsync://repository.lacnic.net/rpki: failed with status exit code: 23
    > Feb 28 16:54:16 rpki-validator3 routinator[2128]: rsync://repository.lacnic.net/rpki: rsync: failed to set times on "/home/rcompton/routinator/.../rsync/repository.lacnic.net/rpki/lacnic/7eef83c3-8e97-4b54-a597-1036cb1dffae": Operation not permitted (1)
    > Feb 28 16:54:16 rpki-validator3 routinator[2128]: rsync://repository.lacnic.net/rpki: rsync: opendir "/home/rcompton/routinator/.../rsync/repository.lacnic.net/rpki/lacnic/7eef83c3-8e97-4b54-a597-1036cb1dffae" failed: Permission denied (13)
    > Feb 28 16:54:16 rpki-validator3 routinator[2128]: rsync://repository.lacnic.net/rpki: rsync: recv_generator: failed to stat "/home/rcompton/routinator/.../rsync/repository.lacnic.net/rpki/lacnic/7eef83c3-8e97-4b54-a597-1036cb1dffae/0f82d16e54d63e1fcbad2873ef9377e70690daad.roa": Permission denied (13)
    > Feb 28 16:54:16 rpki-validator3 routinator[2128]: rsync://repository.lacnic.net/rpki: rsync: recv_generator: failed to stat "/home/rcompton/routinator/.../rsync/repository.lacnic.net/rpki/lacnic/7eef83c3-8e97-4b54-a597-1036cb1dffae/67fd53696c8aeee0f94a9db5d41967d282caea23.roa": Permission denied (13)
    > Feb 28 16:54:16 rpki-validator3 routinator[2128]: rsync://repository.lacnic.net/rpki: rsync: recv_generator: failed to stat "/home/rcompton/routinator/.../rsync/repository.lacnic.net/rpki/lacnic/7eef83c3-8e97-4b54-a597-1036cb1dffae/b56daa0fd6210a6c89a9e60487c2c65e72218f5d.crl": Permission denied (13)
    > Feb 28 16:54:16 rpki-validator3 routinator[2128]: rsync://repository.lacnic.net/rpki: rsync: recv_generator: failed to stat "/home/rcompton/routinator/.../rsync/repository.lacnic.net/rpki/lacnic/7eef83c3-8e97-4b54-a597-1036cb1dffae/b56daa0fd6210a6c89a9e60487c2c65e72218f5d.mft": Permission denied (13)
    > Feb 28 16:54:16 rpki-validator3 routinator[2128]: rsync://repository.lacnic.net/rpki: rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1650) [generator=3.1.2]
    > 
    >  
    >  
    > <image001.png>
    >  
    > Rich Compton    |     Principal Eng     |    314.596.2828
    > 8560 Upland Drive,   Suite B  |  Englewood, CO 80112
    >  
    > The contents of this e-mail message and 
    > any attachments are intended solely for the 
    > addressee(s) and may contain confidential 
    > and/or legally privileged information. If you
    > are not the intended recipient of this message
    > or if this message has been addressed to you 
    > in error, please immediately alert the sender
    > by reply e-mail and then delete this message 
    > and any attachments. If you are not the 
    > intended recipient, you are notified that 
    > any use, dissemination, distribution, copying,
    > or storage of this message or any attachment 
    > is strictly prohibited. -- 
    > RPKI mailing list
    > RPKI at lists.nlnetlabs.nl
    > https://lists.nlnetlabs.nl/mailman/listinfo/rpki

E-MAIL CONFIDENTIALITY NOTICE: 
The contents of this e-mail message and any attachments are intended solely for the addressee(s) and may contain confidential and/or legally privileged information. If you are not the intended recipient of this message or if this message has been addressed to you in error, please immediately alert the sender by reply e-mail and then delete this message and any attachments. If you are not the intended recipient, you are notified that any use, dissemination, distribution, copying, or storage of this message or any attachment is strictly prohibited.