[RPKI] routinator server not updating?

Wed Jul 22 13:21:28 UTC 2020

>> However, I have configured the built-in http server to make it
>> possible to do some monitoring, and it now says (among other
>> things):
>>
>> version: routinator/0.7.1
>> serial: 10
>> last-update-start-at:  2020-06-16 13:00:06.611424671 UTC
>> last-update-start-ago: P22DT77524.959437S
>> last-update-done-at:   2020-06-16 12:50:06.337468507 UTC
>> last-update-done-ago:  P22DT78125.233393164S
>> last-update-duration:  PT129.500793946S
>> valid-roas: 38027
>>
>> So ... last updated ... 22 days ago?!?  That timing mark
>> coincides with when the routinator server was last re-started.
>
> Yikes. The last-update-start-at is after the last-update-done-at, so it
> appears Routinator got stuck somewhere during the update. Can you have
> a quick look in the log whether there is anything suspicious? Probably
> not as you are using the default log level, but maybe we are lucky.

I restarted routinator, but it looks like the same thing happened
shortly after I restarted it:

version: routinator/0.7.1
serial: 8
last-update-start-at:  2020-07-09 14:53:48.960715493 UTC
last-update-start-ago: P12DT78697.297119545S
last-update-done-at:   2020-07-09 14:43:48.746013986 UTC
last-update-done-ago:  P12DT79297.511821052S
last-update-duration:  PT118.571741815S
valid-roas: 41188

I'm running with default log level, the log only contains

Jul 09 15:17:23 xxxxxx routinator[7396]: rsync://rpki-repo.registro.br/repo/jpqPP73EfXFzmKpL7PdBCVK2SCj4XEHMwnjUt83LK9X/0/EC9E81276A6FAD1D8313B38A3894E63665D6A821.mft: stale manifest
Jul 09 15:17:23 xxxxxx routinator[7396]: rsync://rpki-repo.registro.br/repo/jpqPP73EfXFzmKpL7PdBCVK2SCj4XEHMwnjUt83LK9X/0/EC9E81276A6FAD1D8313B38A3894E63665D6A821.crl: stale CRL.
Jul 09 15:29:22 xxxxxx routinator[7396]: rsync://rpki-repo.registro.br/repo/12HT38Qc3jeqZcMnucJKHNEMcWeNPZS38dvGcEfa4ytG/0/13C006D7D29B102844A2AB40D25AEF0B774364C3.mft: stale manifest
Jul 09 15:29:22 xxxxxx routinator[7396]: rsync://rpki-repo.registro.br/repo/12HT38Qc3jeqZcMnucJKHNEMcWeNPZS38dvGcEfa4ytG/0/13C006D7D29B102844A2AB40D25AEF0B774364C3.crl: stale CRL.
Jul 09 15:53:51 xxxxxx routinator[7396]: rsync://rpki-repo.registro.br/repo/12HT38Qc3jeqZcMnucJKHNEMcWeNPZS38dvGcEfa4ytG/0/13C006D7D29B102844A2AB40D25AEF0B774364C3.mft: stale manifest
Jul 09 15:53:51 xxxxxx routinator[7396]: rsync://rpki-repo.registro.br/repo/12HT38Qc3jeqZcMnucJKHNEMcWeNPZS38dvGcEfa4ytG/0/13C006D7D29B102844A2AB40D25AEF0B774364C3.crl: stale CRL.
Jul 09 16:30:23 xxxxxx routinator[7396]: rsync://rpki-repo.registro.br/repo/12HT38Qc3jeqZcMnucJKHNEMcWeNPZS38dvGcEfa4ytG/0/13C006D7D29B102844A2AB40D25AEF0B774364C3.mft: stale manifest
Jul 09 16:30:23 xxxxxx routinator[7396]: rsync://rpki-repo.registro.br/repo/12HT38Qc3jeqZcMnucJKHNEMcWeNPZS38dvGcEfa4ytG/0/13C006D7D29B102844A2AB40D25AEF0B774364C3.crl: stale CRL.
Jul 09 16:30:24 xxxxxx routinator[7396]: rsync://rpki-repo.registro.br/repo/jpqPP73EfXFzmKpL7PdBCVK2SCj4XEHMwnjUt83LK9X/0/EC9E81276A6FAD1D8313B38A3894E63665D6A821.mft: stale manifest
Jul 09 16:30:24 xxxxxx routinator[7396]: rsync://rpki-repo.registro.br/repo/jpqPP73EfXFzmKpL7PdBCVK2SCj4XEHMwnjUt83LK9X/0/EC9E81276A6FAD1D8313B38A3894E63665D6A821.crl: stale CRL.

> Additionally, can you check whether Routinator has any rsync child
> processes left?

Nope, it does not:

% ps axd
...
 7070 ?       Il     143:35.75 |-- /usr/pkg/bin/routinator -c /usr/pkg/etc/rout
21718 ?       I        0:00.00 | `-- /usr/pkg/bin/routinator -c /usr/pkg/etc/ro
...

> Finally, what might help to determine where it got stuck might be a
> list of the last modification times of all the files
> under /var/db/rpki-cache/repository.

Hm, there's some 120.029 files there...

It looks like some files had been updated there even though a
"full update run" had not been done(?):

-rw-r-----  1 routinator  daemon   2067 Jul  4 21:34 ./rsync/repository.lacnic.net/rpki/lacnic/b7e2cbcb-4e1e-4451-ba9f-b839acb5a75f/1ad723cf1d977341fba6a765e30cbb72e98ddc93.roa
-rw-r-----  1 routinator  daemon   1882 Jul  4 23:33 ./rsync/repository.lacnic.net/rpki/lacnic/b7e2cbcb-4e1e-4451-ba9f-b839acb5a75f/056ac5fb3511fc362f849173177b09c06d210e19.roa
-rw-r-----  1 routinator  daemon   2169 Jul  6 17:04 ./rsync/repository.lacnic.net/rpki/lacnic/c20b558a-89e0-4c9e-b6c8-d7c694632120/0230b1ddcee44948473b30e26ce242ef480069ce.roa
-rw-r-----  1 routinator  daemon   2101 Jul  9 09:03 ./rsync/repository.lacnic.net/rpki/lacnic/82bd0309-39fc-4bbc-b121-fff7c80d221e/760a9295e30fafaac20d478dbe02e84b48220235.mft
-rw-r-----  1 routinator  daemon   1069 Jul  9 09:03 ./rsync/repository.lacnic.net/rpki/lacnic/82bd0309-39fc-4bbc-b121-fff7c80d221e/760a9295e30fafaac20d478dbe02e84b48220235.crl

...

and the last updated files seem to be

-rw-r-----  1 routinator  daemon   2424 Jul  9 16:06 ./rrdp/2357259194/data/rpki-repo.as207960.net/repo/as207960-rpki-ca/0/FD8A095FC5925B459392625DB60A9B8AD155EC7B.mft
-rw-r-----  1 routinator  daemon    188 Jul  9 16:06 ./rrdp/2357259194/state.txt
-rw-r-----  1 routinator  daemon    434 Jul  9 16:06 ./rrdp/1626646064/data/cb.rg.net/rpki/RGnet-cb/T-c0qENsBRnNvTPGP4Hco0BdqrE.crl
-rw-r-----  1 routinator  daemon   1920 Jul  9 16:06 ./rrdp/1626646064/data/cb.rg.net/rpki/RGnet-cb/T-c0qENsBRnNvTPGP4Hco0BdqrE.mft
-rw-r-----  1 routinator  daemon    175 Jul  9 16:06 ./rrdp/1626646064/state.txt

The state.txt file contains:

# cat rrdp/1626646064/state.txt
notify-uri: https://cb.rg.net/rrdp/notify.xml
session: 18557da4-9b93-4539-b0ec-cd0408f58bb4
serial: 388
hash: ef3f7b1319704f5e65148e0188ee86085374a3b973cb737fcddfbde8b410436e
# 

but after that time, nothing.

> We have seen RRDP updates for certain servers to take an awfully long
> time, even though there is a timeout set. I always attributed this to
> bytes come trickling in slowly and the connection not be dead but maybe
> I am wrong. I'll definitely double check these timeouts.

Time to adjust log-level to "debug", I think...

Doing a new restart now.

The previous time I had routinator run as "daemon" which doesn't
have a valid login shell, but I changed that to a program-
specific "routinator" user, but that didn't change the behaivour.

>> ...and while nitpicking (these might be relevant to the above
>> main question, "why isn't routinator updating?"):
>>
>>        disable-rsync
>>               A boolean value that, if present and true, turns off
>> the use of rsync.
>>
>> Default value?
>
> Not to go all philosophical, but can an optional value have a default
> value?

"Touché", isn't that the expression?

>>        rsync-command
>>               A string specifying the command to use for running
>> rsync. The default is simply rsync.
>>
>> Searched for in $PATH?
>
> Yes. Apparently there is some weirdness on Windows, but I guess that
> doesn't matter too much.

OK.

Regards,

- Håvard