search

dragonresearch / rpki.net

Dragon Research Labs rpki.net RPKI toolkit
54 stars 30 forks source link

RPKI expiration notice from ca0.rpki.net #858

Closed randyqx closed 6 years ago

randyqx commented 7 years ago 
RGnet's rescert from parent altCA will expire soon:
Certificate chain:
*  [0] uri=rsync://ca0.rpki.net/tal/root.cer expires=2017-05-27 22:33:47
    Contact: Randy Bush, Internet Initiative Japan, randy@psg.com, +1 (206) 356-8341
   [1] uri=rsync://ca0.rpki.net/rpki/altCA/IybeXOrbk5YRyR8CfbVj_MxbneE.cer expires=2018-04-10 22:04:55
    Contact: Randy Bush, RGnet, LLC, randy@psg.com, +1 (206) 356-8341

yet

ryuu.psg.com:/Users/randy> rsync rsync://ca0.rpki.net/tal/root.cer .
ryuu.psg.com:/Users/randy> openssl x509 -in root.cer -inform DER -text | grep 'Not After'
            Not After : May 14 04:38:38 2018 GMT
randyqx commented 7 years ago

the expiration notice is stamped 00:00:04. logs not interesting that i can see

2017-05-16 23:50:15 rpkid[1206]: Resynchronization: keeping object rsync://ca0.rpki.net/rpki/vicwellington/fu8yzeUOxPqT8CUfLoFFrFLti7o.roa
2017-05-17 00:00:03 rpkid[1206]: 200 POST /left-right (2001:418:3807::16) 32.22ms
2017-05-17 00:00:03 rpkid[1206]: 200 POST /left-right (2001:418:3807::16) 46.71ms
2017-05-17 00:00:03 rpkid[1206]: 200 POST /left-right (2001:418:3807::16) 26.86ms
2017-05-17 00:00:04 rpkid[1206]: 200 POST /left-right (2001:418:3807::16) 35.77ms
2017-05-17 00:00:04 rpkid[1206]: 200 POST /left-right (2001:418:3807::16) 24.66ms
2017-05-17 00:00:04 rpkid[1206]: 200 POST /left-right (2001:418:3807::16) 34.41ms
2017-05-17 00:00:04 rpkid[1206]: 200 POST /left-right (2001:418:3807::16) 26.71ms
2017-05-17 00:00:04 rpkid[1206]: 200 POST /left-right (2001:418:3807::16) 34.53ms

this was 20 minutes later

2017-05-17 00:20:11 rpkid[1206]: Child u'rgnet' of tenant u'altCA' not found
2017-05-17 00:20:11 rpkid[1206]: 400 POST /up-down/altCA/rgnet (2001:418:3807::16) 6.62ms
2017-05-17 00:20:11 rpkid[1206]: <rpki.rpkid.main object at 0x7fb5eca7cbd0>: HTTP error contacting <tornado.httpclient.HTTPRequest object at 0x7fb5e012add0>: HTTP 400: Child u'rgnet' not found
2017-05-17 00:20:11 rpkid[1206]: <rpki.rpkid_tasks.PollParentTask {rgnet}>: Couldn't get resource class list from <Parent: rgnet.altCA http://ca0.rpki.net:4404/up-down/altCA/rgnet>, skipping: HTTPError: HTTP 400: Child u'rgnet' not found

irdb utterly uninteresting

2017-05-16 23:50:15 irdbd[1205]: 127.0.0.1:38844 "POST / HTTP/1.1" 200 -
2017-05-16 23:50:15 irdbd[1205]: 127.0.0.1:38848 "POST / HTTP/1.1" 200 -
2017-05-16 23:50:15 irdbd[1205]: 127.0.0.1:38852 "POST / HTTP/1.1" 200 -
2017-05-17 00:20:11 irdbd[1205]: 127.0.0.1:38936 "POST / HTTP/1.1" 200 -
2017-05-17 00:20:12 irdbd[1205]: 127.0.0.1:38940 "POST / HTTP/1.1" 200 -
2017-05-17 00:20:12 irdbd[1205]: 127.0.0.1:38944 "POST / HTTP/1.1" 200 -
2017-05-17 00:20:12 irdbd[1205]: 127.0.0.1:38948 "POST / HTTP/1.1" 200 -
2017-05-17 00:20:12 irdbd[1205]: 127.0.0.1:38954 "POST / HTTP/1.1" 200 -

and i have no idea where michael is getting an expired root.cer

ca0.rpki.net:/root# find / -name root.cer
/usr/share/rpki/tal/root.cer
/var/rcynic/data/unauthenticated/ca0.rpki.net/tal/root.cer

ca0.rpki.net:/root# openssl x509 -in /usr/share/rpki/tal/root.cer -inform DER -text | grep 'Not After'
            Not After : May 14 04:38:38 2018 GMT
ca0.rpki.net:/root# openssl x509 -in /var/rcynic/data/unauthenticated/ca0.rpki.net/tal/root.cer -inform DER -text | grep 'Not After'
            Not After : May 14 04:38:38 2018 GMT
randyqx commented 7 years ago

rcynic log also no smoking gun, though other issue

2017-05-16 11:56:52 rcynic[20269]: HTTP error for https://rrdp.ripe.net/3f8931d2-1608-44b1-923c-14827ff6d8b9/1359/delta.xml: HTTP 599: Timeout
2017-05-16 11:56:54 rcynic[20269]: Exception in callback <functools.partial object at 0x7f49c61e2cb0>: SSLEOFError: EOF occurred in violation of protocol (_ssl.c:590)
2017-05-16 12:11:13 rcynic[20269]: HTTP error for https://gogl-rpki.rarc.net/rrdp/notify.xml: HTTP 599: Timeout
2017-05-16 14:13:14 rcynic[27504]: Network I/O error for https://rrdp.ripe.net/3f8931d2-1608-44b1-923c-14827ff6d8b9/1361/delta.xml: EOF occurred in violation of protocol (_ssl.c:590)
2017-05-16 14:32:00 rcynic[27504]: HTTP error for https://gogl-rpki.rarc.net/rrdp/notify.xml: HTTP 599: Timeout
2017-05-16 17:12:01 rcynic[1542]: HTTP error for https://gogl-rpki.rarc.net/rrdp/notify.xml: HTTP 599: Timeout
2017-05-16 19:39:47 rcynic[5084]: HTTP error for https://rrdp.ripe.net/3f8931d2-1608-44b1-923c-14827ff6d8b9/1505/delta.xml: HTTP 599: Timeout
2017-05-16 19:39:49 rcynic[5084]: Exception in callback <functools.partial object at 0x7f5d2af42578>: SSLEOFError: EOF occurred in violation of protocol (_ssl.c:590)
2017-05-16 19:54:12 rcynic[5084]: HTTP error for https://gogl-rpki.rarc.net/rrdp/notify.xml: HTTP 599: Timeout
2017-05-16 22:33:50 rcynic[13848]: HTTP error for https://rrdp.ripe.net/3f8931d2-1608-44b1-923c-14827ff6d8b9/1507/delta.xml: HTTP 599: Timeout
2017-05-16 22:33:53 rcynic[13848]: Exception in callback <functools.partial object at 0x7f7cc8dda628>: SSLEOFError: EOF occurred in violation of protocol (_ssl.c:590)
2017-05-16 22:51:12 rcynic[13848]: HTTP error for https://gogl-rpki.rarc.net/rrdp/notify.xml: HTTP 599: Timeout
2017-05-17 02:27:38 rcynic[21026]: HTTP error for https://ca0.rpki.net/rrdp/cdaf66c8-bce6-43a7-ab2b-9518a156d221/deltas/36168.xml: HTTP 599: Stream closed
2017-05-17 02:27:38 rcynic[21026]: HTTP error for https://ca0.rpki.net/rrdp/cdaf66c8-bce6-43a7-ab2b-9518a156d221/deltas/36169.xml: HTTP 599: Stream closed
2017-05-17 02:27:39 rcynic[21026]: Exception in callback <functools.partial object at 0x7f4a618d7050>: SSLEOFError: EOF occurred in violation of protocol (_ssl.c:590)
2017-05-17 02:27:39 rcynic[21026]: HTTP error for https://localcert.ripe.net/rrdp//4ecd760c-437e-47d3-ae42-7b5bd0adc93d/10983/delta.xml: HTTP 599: Timeout
2017-05-17 02:27:39 rcynic[21026]: HTTP error for https://localcert.ripe.net/rrdp//4ecd760c-437e-47d3-ae42-7b5bd0adc93d/10984/delta.xml: HTTP 599: Timeout
2017-05-17 02:27:39 rcynic[21026]: HTTP error for https://rrdp.ripe.net/3f8931d2-1608-44b1-923c-14827ff6d8b9/1509/delta.xml: HTTP 599: Timeout
2017-05-17 02:27:41 rcynic[21026]: Exception in callback <functools.partial object at 0x7f4a613f8d60>: SSLEOFError: EOF occurred in violation of protocol (_ssl.c:590)
2017-05-17 02:27:41 rcynic[21026]: Exception in callback <functools.partial object at 0x7f4a613f8e10>: SSLEOFError: EOF occurred in violation of protocol (_ssl.c:590)
2017-05-17 02:27:43 rcynic[21026]: Future exception was never retrieved: Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/tornado/gen.py", line 876, in run
    yielded = self.gen.throw(*exc_info)
  File "/usr/bin/rcynic", line 1018, in _rrdp_fetch_data_file
    retrieval, response = yield self._https_fetch_url(url, lambda data: (sha256.update(data), xml_file.write(data)))
  File "/usr/lib/python2.7/dist-packages/tornado/gen.py", line 870, in run
    value = future.result()
  File "/usr/lib/python2.7/dist-packages/tornado/concurrent.py", line 215, in result
    raise_exc_info(self._exc_info)
  File "/usr/lib/python2.7/dist-packages/tornado/gen.py", line 876, in run
    yielded = self.gen.throw(*exc_info)
  File "/usr/bin/rcynic", line 933, in _https_fetch_url
    request_timeout = args.https_timeout)
  File "/usr/lib/python2.7/dist-packages/tornado/gen.py", line 870, in run
    value = future.result()
  File "/usr/lib/python2.7/dist-packages/tornado/concurrent.py", line 215, in result
    raise_exc_info(self._exc_info)
  File "<string>", line 3, in raise_exc_info
HTTPError: HTTP 599: Stream closed
2017-05-17 02:27:43 rcynic[21026]: Future exception was never retrieved: Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/tornado/gen.py", line 876, in run
    yielded = self.gen.throw(*exc_info)
  File "/usr/bin/rcynic", line 1018, in _rrdp_fetch_data_file
    retrieval, response = yield self._https_fetch_url(url, lambda data: (sha256.update(data), xml_file.write(data)))
  File "/usr/lib/python2.7/dist-packages/tornado/gen.py", line 870, in run
    value = future.result()
  File "/usr/lib/python2.7/dist-packages/tornado/concurrent.py", line 215, in result
    raise_exc_info(self._exc_info)
  File "/usr/lib/python2.7/dist-packages/tornado/gen.py", line 876, in run
    yielded = self.gen.throw(*exc_info)
  File "/usr/bin/rcynic", line 933, in _https_fetch_url
    request_timeout = args.https_timeout)
  File "/usr/lib/python2.7/dist-packages/tornado/gen.py", line 870, in run
    value = future.result()
  File "/usr/lib/python2.7/dist-packages/tornado/concurrent.py", line 215, in result
    raise_exc_info(self._exc_info)
  File "<string>", line 3, in raise_exc_info
HTTPError: HTTP 599: Timeout
2017-05-17 02:45:12 rcynic[21026]: HTTP error for https://gogl-rpki.rarc.net/rrdp/notify.xml: HTTP 599: Timeout

i suspect google's publication point is not available

sraustein commented 7 years ago

What I've got so far is that something does indeed appear to be stuck in this VM's rcynic DB:

rpki=> select * from rcynicdb_retrieval where uri like '%root%';
   id    |                                 uri                                  |            started            |           finished            | successful 
---------+----------------------------------------------------------------------+-------------------------------+-------------------------------+------------
       3 | rsync://rpki.apnic.net/repository/apnic-rpki-root-lacnic-origin.cer  | 2016-05-19 14:36:02.656772+00 | 2016-05-19 14:36:04.436565+00 | t
       5 | rsync://rpki.apnic.net/repository/apnic-rpki-root-afrinic-origin.cer | 2016-05-19 14:36:02.648029+00 | 2016-05-19 14:36:04.478253+00 | t
 5947528 | rsync://rpki.apnic.net/repository/apnic-rpki-root-arin-origin.cer    | 2017-05-16 06:56:01.846586+00 | 2017-05-16 06:56:04.153799+00 | t
  222809 | rsync://ca0.rpki.net/tal/root.cer                                    | 2016-06-01 02:36:02.041964+00 | 2016-06-01 02:36:02.187593+00 | t
 5345213 | rsync://rpki.apnic.net/repository/apnic-rpki-root-iana-origin.cer    | 2017-03-06 05:56:02.604532+00 | 2017-03-06 05:56:06.248416+00 | t
 5953263 | rsync://rpki.apnic.net/repository/apnic-rpki-root-ripe-origin.cer    | 2017-05-17 00:56:02.270815+00 | 2017-05-17 00:56:07.140465+00 | t
 5959923 | rsync://rpki.apnic.net/repository/apnic-rpki-root-arin-origin.cer    | 2017-05-17 22:56:02.249318+00 | 2017-05-17 22:56:04.544964+00 | t
 5959924 | rsync://rpki.apnic.net/repository/apnic-rpki-root-iana-origin.cer    | 2017-05-17 22:56:02.252482+00 | 2017-05-17 22:56:04.553167+00 | t
 5959926 | rsync://rpki.apnic.net/repository/apnic-rpki-root-ripe-origin.cer    | 2017-05-17 22:56:02.261375+00 | 2017-05-17 22:56:04.569963+00 | t
 5959927 | rsync://rpki.apnic.net/repository/apnic-rpki-root-afrinic-origin.cer | 2017-05-17 22:56:02.264401+00 | 2017-05-17 22:56:04.578257+00 | t
 5959929 | rsync://ca0.rpki.net/tal/root.cer                                    | 2017-05-17 22:56:04.531033+00 | 2017-05-17 22:56:11.263095+00 | t
 5959930 | rsync://rpki.apnic.net/repository/apnic-rpki-root-lacnic-origin.cer  | 2017-05-17 22:56:04.533988+00 | 2017-05-17 22:56:11.288113+00 | t
(12 rows)

rpki=> select id, uri, ski, sha256, retrieved_id from  rcynicdb_rpkiobject where retrieved_id = 222809;
   id   |                uri                |                   ski                    |                              sha256                              | retrieved_id 
--------+-----------------------------------+------------------------------------------+------------------------------------------------------------------+--------------
 456987 | rsync://ca0.rpki.net/tal/root.cer | 621a089feb4926cf5454e980f4cf59ee1aaaa665 | 141cf6323b4bae655cae27b25025e4e29a31aaf8ed9b16fa8f899da23f7550c9 |       222809
(1 row)

rpki=> select id, uri, ski, sha256, retrieved_id from  rcynicdb_rpkiobject where retrieved_id = 5959929;
 id | uri | ski | sha256 | retrieved_id 
----+-----+-----+--------+--------------
(0 rows)

rpki=> select id, uri, ski, sha256, retrieved_id from  rcynicdb_rpkiobject where uri = 'rsync://ca0.rpki.net/tal/root.cer';
   id   |                uri                |                   ski                    |                              sha256                              | retrieved_id 
--------+-----------------------------------+------------------------------------------+------------------------------------------------------------------+--------------
 456987 | rsync://ca0.rpki.net/tal/root.cer | 621a089feb4926cf5454e980f4cf59ee1aaaa665 | 141cf6323b4bae655cae27b25025e4e29a31aaf8ed9b16fa8f899da23f7550c9 |       222809
(1 row)

Don't (yet) know why it's keeping the old root.cer object rather than the new one.

randyqx commented 6 years ago

this cleared magically at the expiration date