[RPKI] "Permission denied (13)" rsync errors
Compton, Rich A
Rich.Compton at charter.com
Tue Mar 3 22:52:22 UTC 2020
Hi, yeah, I am starting routinator with a systemd script on Centos7. I think there is an issue with the rsync commands that are launched by routinator that prevent rsync from successfully putting files into the ".rpki-cache/repository/" directories.
Here's what my systemd script looks like:
[Unit]
Description=Routinator RPKI Validator and RTR Server
After=network.target
[Service]
Type=simple
User=routinator
Group=routinator
ExecStart=/home/routinator/.cargo/bin/routinator -v server --http 127.0.0.1:8080 --rtr <IPv4 IP>:8323 --rtr [<IPv6 IP>]:8323
TimeoutStartSec=0
[Install]
WantedBy=default.target
On 3/3/20, 12:35 PM, "Alex Band" <alex at nlnetlabs.nl> wrote:
Hi Rich,
Most errors look about right. CNNIC has pretty frequent reachability issues, as well as objects going stale. At this moment registro.br also has some stale CRLs and manifests as well that they’re looking into.
Most of these issues come and go, it’s not realistic that everything is perfect all the time. This wasn’t the case when there was practically only hosted RPKI and just five RIR repositories and now, with the uptake of delegated RPKI there’s bound to be more transient issues as people get started and gain experience.
What does concern me are the “Permission denied (13)” errors you’re getting on your rsync connections. I haven’t seen that before and you’ve had it with LACNIC, JPNIC and ARIN now.
-Alex
> On 3 Mar 2020, at 17:27, Compton, Rich A via RPKI <rpki at lists.nlnetlabs.nl> wrote:
>
> 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.
> --
> 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.
More information about the RPKI
mailing list