Possible memory leak when using RIPE-NCC rpki-validator-3 as a source

[dotwaffle]

I'm just doing some playing around in Docker, and I noticed what could be a memory leak.

2:45:55 [dotwaffle@hasselhoff:~] % ps -Fp $(pgrep -d, -x gortr) | sort -k6nr | head -n1
uuidd    12483 12466  0 2245623 8887096 3 Nov13 ?      00:03:06 ./gortr -refresh=60 -cache=http://ripe-rpkivalidator3:8080/api/export.json -metrics.addr=:8081 -ssh.bind=:8022 -ssh.key=/run/secrets/cfrpki-ssh-private.pem -ssh.auth.user=rpki -ssh.auth.password=rpki -ssh.auth.key.bypass=true -ssh.method.password=true -bind=:8023 -tls.bind=:8082 -tls.cert=/run/secrets/cfrpki-tls-public.pem -tls.key=/run/secrets/cfrpki-tls-private.pem -checktime=false -verify=false

It appears to be using 8.6GB of memory after running overnight!

No valid client has ever connected to the daemon, which is running in a Docker container, as is the validator. There have been some invalid connection attempts (presumably port scans):

3:02:20 [dotwaffle@very:~] % docker service logs rpki_ripe-gortr 2>&1 | grep connection | tail -n1
rpki_ripe-gortr.1.pcgn3tuvgan1@hasselhoff    | time="2019-11-13T22:38:27Z" level=info msg="Accepted tcp connection from 10.255.0.3:33736 (1/0)"
3:02:33 [dotwaffle@very:~] % docker service logs rpki_ripe-gortr 2>&1 | grep connection | wc -l   
117
3:09:46 [dotwaffle@very:~] % docker service logs rpki_ripe-gortr 2>&1 | lgrep 'msg=~(Error)' | lcut -v msg | sort | uniq -c | sort -n
      1 msg="Error updating: Get http://ripe-rpkivalidator3:8080/api/export.json: dial tcp: lookup ripe-rpkivalidator3 on 127.0.0.11:53: no such host"
      1 msg="Error with ssh client 10.255.0.2:61497: EOF"
      1 msg="Error with ssh client 10.255.0.3:26417: EOF"
     39 msg="Error EOF"
     74 msg="Error unexpected EOF"

These do not correlate with the times memory usage jumped: (times are UTC+11 in this graph, whereas all timestamps elsewhere are in UTC, sorry!)

The source json is 13MB big:

2:49:39 [dotwaffle@very:~] % curl -s -H "Accept: text/json" https://(hidden):(hidden)@(hidden)/ripe/api/export.json | wc
 582092 1844040 13307887
2:55:26 [dotwaffle@very:~] % curl -s -H "Accept: text/json" https://(hidden):(hidden)@(hidden)/ripe/api/export.json | jq '.roas|length'
116418

Last relevant logs:

2:59:42 [dotwaffle@very:~] % docker service logs rpki_ripe-gortr
rpki_ripe-gortr.1.pcgn3tuvgan1@hasselhoff    | time="2019-11-13T14:53:42Z" level=info msg="Enabling ssh with the following authentications: password=true, key=false"
rpki_ripe-gortr.1.pcgn3tuvgan1@hasselhoff    | time="2019-11-13T14:53:42Z" level=error msg="Get http://ripe-rpkivalidator3:8080/api/export.json: dial tcp: lookup ripe-rpkivalidator3 on 127.0.0.11:53: no such host"
rpki_ripe-gortr.1.pcgn3tuvgan1@hasselhoff    | time="2019-11-13T14:53:42Z" level=error msg="Error updating: Get http://ripe-rpkivalidator3:8080/api/export.json: dial tcp: lookup ripe-rpkivalidator3 on 127.0.0.11:53: no such host"
rpki_ripe-gortr.1.pcgn3tuvgan1@hasselhoff    | time="2019-11-13T14:54:54Z" level=info msg="New update (45006 uniques, 45006 total prefixes). 0 bytes. Updating sha256 hash  -> 3913b0850dad88eabbbb6b91d6e87766a7a247e5b3c854d1ea7d7ec4d54e9cac"
rpki_ripe-gortr.1.pcgn3tuvgan1@hasselhoff    | time="2019-11-13T14:54:54Z" level=info msg="Updated added, new serial 1"
rpki_ripe-gortr.1.pcgn3tuvgan1@hasselhoff    | time="2019-11-13T14:57:11Z" level=info msg="New update (116358 uniques, 116358 total prefixes). 0 bytes. Updating sha256 hash 3913b0850dad88eabbbb6b91d6e87766a7a247e5b3c854d1ea7d7ec4d54e9cac -> 7fbacead1f9dc6968a5c3f7caf82f5ee0d02988ae4d9f6f9ecb16a232a253ab8"
rpki_ripe-gortr.1.pcgn3tuvgan1@hasselhoff    | time="2019-11-13T14:57:11Z" level=info msg="Updated added, new serial 2"
rpki_ripe-gortr.1.pcgn3tuvgan1@hasselhoff    | time="2019-11-13T14:58:11Z" level=info msg="File http://ripe-rpkivalidator3:8080/api/export.json is identical to the previous version"
[...]
rpki_ripe-gortr.1.pcgn3tuvgan1@hasselhoff    | time="2019-11-14T02:23:17Z" level=info msg="New update (116418 uniques, 116418 total prefixes). 0 bytes. Updating sha256 hash f9ffaa35bc3fd3b892870e4cd0e82e2dc9e9a7ea8bff864ff793d9090e809984 -> 2e764d23e2a315baf6ff504c3a2e2269bf8fcdc3a08f95a94ea587f5c2f3abcd"
rpki_ripe-gortr.1.pcgn3tuvgan1@hasselhoff    | time="2019-11-14T02:23:17Z" level=info msg="Updated added, new serial 33"
rpki_ripe-gortr.1.pcgn3tuvgan1@hasselhoff    | time="2019-11-14T02:24:17Z" level=info msg="File http://ripe-rpkivalidator3:8080/api/export.json is identical to the previous version"
[...repeats last message...]

Finally, other gortr instances running against public instances, using the same binary, seem to be operating fine:

3:20:36 [dotwaffle@hasselhoff:~] % ps -Fp $(pgrep -d, -x gortr)             
UID        PID  PPID  C    SZ   RSS PSR STIME TTY          TIME CMD
uuidd    12483 12466  0 2245623 8887096 7 Nov13 ?      00:03:14 ./gortr -refresh=60 -cache=http://ripe-rpkivalidator3:8080/api/export.json -metrics.addr=:8081 -ssh.bind=:8022 -ssh.key=/run/secrets/cfrpki-ssh-private.pem -ssh.auth.user=rpki -ssh.auth.password=rpki -ssh.auth.key.bypass=true -ssh.method.password=true -bind=:8023 -tls.bind=:8082 -tls.cert=/run/secrets/cfrpki-tls-public.pem -tls.key=/run/secrets/cfrpki-tls-private.pem -checktime=false -verify=false
uuidd    12915 12898  0 80498 283356  5 Nov13 ?        00:02:54 ./gortr -refresh=60 -cache=http://cf-octorpki:8080/output.json -metrics.addr=:8081 -ssh.bind=:8022 -ssh.key=/run/secrets/cfrpki-ssh-private.pem -ssh.auth.user=rpki -ssh.auth.password=rpki -ssh.auth.key.bypass=true -ssh.method.password=true -bind=:8023 -tls.bind=:8082 -tls.cert=/run/secrets/cfrpki-tls-public.pem -tls.key=/run/secrets/cfrpki-tls-private.pem -verify.key=/run/secrets/cfrpki-json-public.pem
uuidd    13371 13354  0 114515 421220 3 Nov13 ?        00:02:08 ./gortr -refresh=300 -cache=http://ripeval.labs.lacnic.net:8080/export.json -metrics.addr=:8081 -ssh.bind=:8022 -ssh.key=/run/secrets/cfrpki-ssh-private.pem -ssh.auth.user=rpki -ssh.auth.password=rpki -ssh.auth.key.bypass=true -ssh.method.password=true -bind=:8023 -tls.bind=:8082 -tls.cert=/run/secrets/cfrpki-tls-public.pem -tls.key=/run/secrets/cfrpki-tls-private.pem -checktime=false -verify=false
uuidd    13647 13630  0 232763 824528 7 Nov13 ?        00:03:11 ./gortr -refresh=60 -cache=https://rpki.cloudflare.com/rpki.json -metrics.addr=:8081 -ssh.bind=:8022 -ssh.key=/run/secrets/cfrpki-ssh-private.pem -ssh.auth.user=rpki -ssh.auth.password=rpki -ssh.auth.key.bypass=true -ssh.method.password=true -bind=:8023 -tls.bind=:8082 -tls.cert=/run/secrets/cfrpki-tls-public.pem -tls.key=/run/secrets/cfrpki-tls-private.pem -verify.key=cf.pub
uuidd    13903 13886  0 232613 894204 1 Nov13 ?        00:02:21 ./gortr -refresh=300 -cache=https://rpki.gin.ntt.net/api/export.json -metrics.addr=:8081 -ssh.bind=:8022 -ssh.key=/run/secrets/cfrpki-ssh-private.pem -ssh.auth.user=rpki -ssh.auth.password=rpki -ssh.auth.key.bypass=true -ssh.method.password=true -bind=:8023 -tls.bind=:8082 -tls.cert=/run/secrets/cfrpki-tls-public.pem -tls.key=/run/secrets/cfrpki-tls-private.pem -checktime=false -verify=false
uuidd    14292 14275  0 114518 421132 1 Nov13 ?        00:02:13 ./gortr -refresh=300 -cache=http://localcert.ripe.net:8088/export.json -metrics.addr=:8081 -ssh.bind=:8022 -ssh.key=/run/secrets/cfrpki-ssh-private.pem -ssh.auth.user=rpki -ssh.auth.password=rpki -ssh.auth.key.bypass=true -ssh.method.password=true -bind=:8023 -tls.bind=:8082 -tls.cert=/run/secrets/cfrpki-tls-public.pem -tls.key=/run/secrets/cfrpki-tls-private.pem -checktime=false -verify=false

Docker image: sha256:694635c16932987185a3d8d1056ef5ae287e799e7d36981a573d8baa8fc1e752 (cloudflare/gortr:latest which is 8 days old)

This is a toy implementation for my own research purposes, I've not killed the daemon (yet) so if there's anything I can provide, please let me know. I figured it was worth letting you know!

[dotwaffle]

Actually, I think this might be our old friend MADV_FREE which is default in Go1.12 and later. The kernel will free the memory under memory pressure. Unfortunately, that is screwing up my alerting...

I'm going to try with GODEBUG=madvdontneed=1 as an environment variable to see if that stops it. I'm still curious why the memory usage massively increased at those two times though.

[lspgn]

Let me know what you find! Thanks for the investigation! I will take a look as well.

[dotwaffle]

It's been 4 hours and the memory usage is reasonable still. I'll keep it running for 24 hours to see whether it spikes overnight. Thanks!

[dotwaffle]

Ahah! So, running overnight, memory usage was low and stable with GODEBUG=madvdontneed=1 set. However, I stopped the RIPE NCC rpki-validator-3, and about 10 minutes later memory usage ballooned to nearly 4GB.

Here's the relevant logs:

time="2019-11-15T00:40:28Z" level=info msg="File http://ripe-rpkivalidator3:8080/api/export.json is identical to the previous version"
[... run docker service scale rpki_ripe-rpkivalidator3=0 rpki_cf-octorpki=0 ...]
time="2019-11-15T00:41:28Z" level=error msg="Get http://ripe-rpkivalidator3:8080/api/export.json: dial tcp: lookup ripe-rpkivalidator3 on 127.0.0.11:53: no such host"
time="2019-11-15T00:41:28Z" level=error msg="Error updating: Get http://ripe-rpkivalidator3:8080/api/export.json: dial tcp: lookup ripe-rpkivalidator3 on 127.0.0.11:53: no such host"
time="2019-11-15T00:42:28Z" level=error msg="Get http://ripe-rpkivalidator3:8080/api/export.json: dial tcp: lookup ripe-rpkivalidator3 on 127.0.0.11:53: no such host"
time="2019-11-15T00:42:28Z" level=error msg="Error updating: Get http://ripe-rpkivalidator3:8080/api/export.json: dial tcp: lookup ripe-rpkivalidator3 on 127.0.0.11:53: no such host"
time="2019-11-15T00:43:28Z" level=error msg="Get http://ripe-rpkivalidator3:8080/api/export.json: dial tcp: lookup ripe-rpkivalidator3 on 127.0.0.11:53: no such host"
time="2019-11-15T00:43:28Z" level=error msg="Error updating: Get http://ripe-rpkivalidator3:8080/api/export.json: dial tcp: lookup ripe-rpkivalidator3 on 127.0.0.11:53: no such host"
time="2019-11-15T00:44:28Z" level=error msg="Get http://ripe-rpkivalidator3:8080/api/export.json: dial tcp: lookup ripe-rpkivalidator3 on 127.0.0.11:53: no such host"
time="2019-11-15T00:44:28Z" level=error msg="Error updating: Get http://ripe-rpkivalidator3:8080/api/export.json: dial tcp: lookup ripe-rpkivalidator3 on 127.0.0.11:53: no such host"
time="2019-11-15T00:45:28Z" level=error msg="Get http://ripe-rpkivalidator3:8080/api/export.json: dial tcp: lookup ripe-rpkivalidator3 on 127.0.0.11:53: no such host"
time="2019-11-15T00:45:28Z" level=error msg="Error updating: Get http://ripe-rpkivalidator3:8080/api/export.json: dial tcp: lookup ripe-rpkivalidator3 on 127.0.0.11:53: no such host"
time="2019-11-15T00:46:28Z" level=error msg="Get http://ripe-rpkivalidator3:8080/api/export.json: dial tcp: lookup ripe-rpkivalidator3 on 127.0.0.11:53: no such host"
time="2019-11-15T00:46:28Z" level=error msg="Error updating: Get http://ripe-rpkivalidator3:8080/api/export.json: dial tcp: lookup ripe-rpkivalidator3 on 127.0.0.11:53: no such host"
time="2019-11-15T00:47:28Z" level=error msg="Get http://ripe-rpkivalidator3:8080/api/export.json: dial tcp: lookup ripe-rpkivalidator3 on 127.0.0.11:53: no such host"
time="2019-11-15T00:47:28Z" level=error msg="Error updating: Get http://ripe-rpkivalidator3:8080/api/export.json: dial tcp: lookup ripe-rpkivalidator3 on 127.0.0.11:53: no such host"
time="2019-11-15T00:48:28Z" level=error msg="Get http://ripe-rpkivalidator3:8080/api/export.json: dial tcp: lookup ripe-rpkivalidator3 on 127.0.0.11:53: no such host"
time="2019-11-15T00:48:28Z" level=error msg="Error updating: Get http://ripe-rpkivalidator3:8080/api/export.json: dial tcp: lookup ripe-rpkivalidator3 on 127.0.0.11:53: no such host"
[... sometimes after this point, but before 00:49:30, memory balloons ...]
time="2019-11-15T00:49:26Z" level=info msg="Accepted tcp connection from 10.255.0.3:44954 (1/0)"
time="2019-11-15T00:49:26Z" level=error msg="Error unexpected EOF"
time="2019-11-15T00:49:26Z" level=info msg="Disconnecting client 10.255.0.3:44954 (v0) / Serial: 0"
time="2019-11-15T00:49:26Z" level=info msg="Accepted tcp connection from 10.255.0.3:34520 (1/0)"
time="2019-11-15T00:49:26Z" level=error msg="Error unexpected EOF"
time="2019-11-15T00:49:26Z" level=info msg="Disconnecting client 10.255.0.3:34520 (v0) / Serial: 0"
time="2019-11-15T00:49:28Z" level=error msg="Get http://ripe-rpkivalidator3:8080/api/export.json: dial tcp: lookup ripe-rpkivalidator3 on 127.0.0.11:53: no such host"
time="2019-11-15T00:49:28Z" level=error msg="Error updating: Get http://ripe-rpkivalidator3:8080/api/export.json: dial tcp: lookup ripe-rpkivalidator3 on 127.0.0.11:53: no such host"
time="2019-11-15T00:49:28Z" level=info msg="Accepted tcp connection from 10.255.0.3:49090 (1/0)"
time="2019-11-15T00:49:29Z" level=error msg="Error unexpected EOF"
time="2019-11-15T00:49:29Z" level=info msg="Disconnecting client 10.255.0.3:49090 (v0) / Serial: 0"
time="2019-11-15T00:49:30Z" level=info msg="Accepted tcp connection from 10.255.0.3:33408 (1/0)"
time="2019-11-15T00:49:31Z" level=error msg="Error unexpected EOF"
time="2019-11-15T00:49:31Z" level=info msg="Disconnecting client 10.255.0.3:33408 (v0) / Serial: 0"
time="2019-11-15T00:49:32Z" level=info msg="Accepted tcp connection from 10.255.0.3:40098 (1/0)"

The conditions seem to be:

1. Having a gortr daemon running for a while with a good source of data to import.
2. A burst of connecting clients that get timed out before finishing connection setup.
3. The data source not to be signed (i.e. verify=false, checktime=false) -- stopping octorpki didn't see the same ballooning memory usage, and that has verify=true. This may be a false report condition as the gortr attached to octorpki does not have those "Disconnecting client" messages.

Memory is never released afterwards, even with MADV_DONTNEED instead of MADV_FREE, and in fact gets higher a little. IMO, there's definitely some pointer being held somewhere that is preventing the data from being freed.

For reference, the memory ballooning instance has:

    ports:
      - target: 8081 # metrics
        published: 8181
        protocol: tcp 
        mode: ingress
      - target: 8082 # tls
        published: 8182
        protocol: tcp 
        mode: ingress
      - target: 8022 # ssh
        published: 8122
        protocol: tcp 
        mode: ingress
      - target: 8023 # raw
        published: 8123
        protocol: tcp 
        mode: ingress

whereas the non-ballooning gortr has:

    ports:
      - target: 8081 # metrics
        published: 8281
        protocol: tcp
        mode: ingress
      - target: 8082 # tls
        published: 8282
        protocol: tcp
        mode: ingress
      - target: 8022 # ssh
        published: 8222
        protocol: tcp
        mode: ingress
      - target: 8023 # raw
        published: 8223
        protocol: tcp
        mode: ingress

It's not clear from the logs which port is being connected to, but I imagine 8181 (metrics) and 8122 (ssh) are more port-scanable than others. Unfortunately, the true source-IPs are hidden because Docker Swarm proxies the connection so it always looks like it comes from private space :(

Let me know if there's anything else I can provide, including the docker-compose.yml stack file if you want to debug yourself.

[lspgn]

Thank you so much for all the details.
Do you mind giving me the -version details?

My docker version is sha256:a62e33b75ec47b4ca288dbd3e93d48307d1b0d03f9288220f30277b58f59cbb7 and cannot fetch the other one:

$ docker run -ti cloudflare/gortr@sha256:694635c16932987185a3d8d1056ef5ae287e799e7d36981a573d8baa8fc1e752
Unable to find image 'cloudflare/gortr@sha256:694635c16932987185a3d8d1056ef5ae287e799e7d36981a573d8baa8fc1e752' locally
docker: Error response from daemon: received unexpected HTTP status: 500 Internal Server Error.```

[dotwaffle]

I have the same image as you, I just accidentally took the Id rather than the repo digest ;)