search

bgp / stayrtr

RPKI-To-Router server implementation in Go
BSD 3-Clause "New" or "Revised" License
85 stars 13 forks source link

serial is updated but FetchFile returns 304 for objects and slurm is local and not changed #114

Closed netixx closed 2 months ago

netixx commented 4 months ago

Hello,

I added the serial metric in https://github.com/bgp/stayrtr/pull/113 and then I saw that it was continuously increasing.

In the logs, I see that the objects are not updated:

time="2024-02-27T14:53:15Z" level=info msg="HTTP 304 Not modified for http://rpki-validator-rpki-client/objects/validated"
time="2024-02-27T14:53:16Z" level=info msg="New update (517256 uniques, 517256 total prefixes, 51 vaps, 2 router keys)."

However, I also see that a new "update" is triggered.

I have a static slurm.json file provided as a local path in the container (via -slurm /slurm.json option), and it's never updated.

I think the serial should only be updated if the vrps are updated or the slurm is changed, and that seems to be what the code want's to do as well:

// Only process the first time after there is either a cache or SLURM
// update.
if cacheUpdated || slurmNotPresentOrUpdated {

So I think there is unexpected behavior in :

slurmNotPresentOrUpdated, err = s.updateSlurm(slurmFile)

Maybe the FetchConfig could maintain a hash of the file (when it's a local file) to see if it has been modified (emulate etag behavior for local files) ? Or maybe it should be in the state object ?

I you provide guidance I am happy to implement :)

job commented 4 months ago

Are you sure nothing was updated? The rpki-client JSON output contains a per-VRP expiration timestamp, so it could be that one or two VRPs expired, even though the source file didn’t change. The mere passing of time can cause change.

netixx commented 4 months ago

I am seeing

HTTP 304 Not modified for http://rpki-validator-rpki-client/objects/validated

in the logs, so I know that I exit here

        return nil, fhttp.StatusCode, true, HttpNotModified{
                File: file,
            }

which means that updateFile returns false, err, and thus (if this is correct :) ) this is not what triggers the serial update. I have a relatively aggressive refresh interval (5 minutes much lower than the run interval of rpki-client, which is 15 minutes), so the file actually doesn't change as much.

Upon further inspection, I see that there is a check for actual sha change in the updateFile, but not in the updateSlurm func.

hsum := newSHA256(data)
    if s.lasthash != nil {
        cres := bytes.Compare(s.lasthash, hsum)
        if cres == 0 {
            return false, IdenticalFile{File: file}
        }
    }

maybe a similar block needs to be added on the slurm func ?

(Thanks for rpki-client btw, I am using this wrapper: https://github.com/ties/rpki-client-web/blob/27a08aaec3244e5183b37ab511d3bd3d690c26f0/rpkiclientweb/web.py#L74)

netixx commented 4 months ago

I tried a fix by using the lastUpdate time of the slurm file and doing a sha when on disk: https://github.com/netixx/stayrtr/blob/local-file-cache/utils/utils.go#L163

but now I get what I think is another issue:

ime="2024-02-27T15:52:47Z" level=error msg="Slurm: EOF"
time="2024-02-27T15:52:48Z" level=info msg="new cache file: Updating sha256 hash  -> f966bf54062d389cccee677118cb9b94839a34c160f018361cc73eb1278c93da"
time="2024-02-27T15:52:50Z" level=info msg="New update (517289 uniques, 517289 total prefixes, 51 vaps, 2 router keys)."
time="2024-02-27T15:52:52Z" level=info msg="Updated added, new serial 0"
time="2024-02-27T15:52:52Z" level=info msg="StayRTR Server started (sessionID:12203, refresh:3600, retry:600, expire:7200)"
time="2024-02-27T15:57:52Z" level=info msg="HTTP 304 Not modified for /slurm.json"
time="2024-02-27T15:57:52Z" level=info msg="HTTP 304 Not modified for http://rpki-validator-rpki-client/objects/validated"
time="2024-02-27T15:57:53Z" level=info msg="New update to old state (517288 uniques, 517288 total prefixes). (old 517342 - new 517288)"
time="2024-02-27T15:57:56Z" level=info msg="Updated added, new serial 1"
time="2024-02-27T16:02:52Z" level=info msg="HTTP 304 Not modified for /slurm.json"
time="2024-02-27T16:02:52Z" level=info msg="HTTP 304 Not modified for http://rpki-validator-rpki-client/objects/validated"
time="2024-02-27T16:02:53Z" level=info msg="New update to old state (517288 uniques, 517288 total prefixes). (old 517341 - new 517288)"
time="2024-02-27T16:02:56Z" level=info msg="Updated added, new serial 2"
time="2024-02-27T16:07:52Z" level=info msg="HTTP 304 Not modified for /slurm.json"
time="2024-02-27T16:07:53Z" level=info msg="new cache file: Updating sha256 hash f966bf54062d389cccee677118cb9b94839a34c160f018361cc73eb1278c93da -> a20adbde53f39b271639f824f722d4c49e0fb7e26eb3029bd4ea875d25fefe1e"
time="2024-02-27T16:07:55Z" level=info msg="New update (517292 uniques, 517292 total prefixes, 51 vaps, 2 router keys)."
time="2024-02-27T16:07:58Z" level=info msg="Updated added, new serial 3"
time="2024-02-27T16:12:52Z" level=info msg="HTTP 304 Not modified for /slurm.json"
2024/02/27 16:12:52 Unsolicited response received on idle HTTP channel starting with "\x1f\x8b\b\x00\x00\x00\x00\x00\x00\x03\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00"; err=<nil>
time="2024-02-27T16:12:52Z" level=info msg="HTTP 304 Not modified for http://rpki-validator-rpki-client/objects/validated"
time="2024-02-27T16:12:53Z" level=info msg="New update to old state (517292 uniques, 517292 total prefixes). (old 517345 - new 517292)"
time="2024-02-27T16:12:56Z" level=info msg="Updated added, new serial 4"
time="2024-02-27T16:17:52Z" level=info msg="HTTP 304 Not modified for /slurm.json"
time="2024-02-27T16:17:52Z" level=info msg="HTTP 304 Not modified for http://rpki-validator-rpki-client/objects/validated"
time="2024-02-27T16:17:53Z" level=info msg="New update to old state (517292 uniques, 517292 total prefixes). (old 517345 - new 517292)"
time="2024-02-27T16:17:55Z" level=info msg="Updated added, new serial 5"
time="2024-02-27T16:22:52Z" level=info msg="HTTP 304 Not modified for /slurm.json"
time="2024-02-27T16:22:52Z" level=info msg="HTTP 304 Not modified for http://rpki-validator-rpki-client/objects/validated"
time="2024-02-27T16:22:53Z" level=info msg="New update to old state (517292 uniques, 517292 total prefixes). (old 517345 - new 517292)"
time="2024-02-27T16:22:55Z" level=info msg="Updated added, new serial 6"

It seems that s.server.CountSDs() != count is always triggered (notice how the same number old=517345 comes back, and the sha hash of the cache file has not been updated between those serial increase.

job commented 4 months ago

I meant to say that there always are ROAs about to expire:

feather$ date
Tue Feb 27 16:32:28 UTC 2024

feather$ curl -s https://console.rpki-client.org/rpki.csv | awk --csv '{ print $NF }' | sort | head -1
1709051516

feather$ date -r 1709051516
Tue Feb 27 16:31:56 UTC 2024

This expiration moment is communicated from rpki-client to StayRTR via the "expires": field, StayRTR tracks those timestamps and yeets ROAs from its internal database when the moment elapses. This will cause an update to be send to the RTR clients, and a serial increase.

Have you excluded that this is what you are seeing? (I'm not excluding the possibility that there improvements to be made to stayrtr, but we have to make sure what exactly we're seeing) :-)

job commented 4 months ago

BTW - rpki-client-web is a cool project, but there also might be benefit to having as little middleware in the pipeline as possible, for example:

while true; do rpki-client -j -m; sleep 300; done in as one process, and stayrtr -cache /var/lib/rpki-client/json as another process cuts out the webserver in the middle. Stayrtr can just poll the filesystem. The -m flag gives you metrics in OpenMetrics format in /var/lib/rpki-client/metrics which you can load into grafana.

job commented 4 months ago

Mmm... from your log:

time="2024-02-27T16:17:52Z" level=info msg="HTTP 304 Not modified for /slurm.json"
time="2024-02-27T16:17:52Z" level=info msg="HTTP 304 Not modified for http://rpki-validator-rpki-client/objects/validated"
time="2024-02-27T16:17:53Z" level=info msg="New update to old state (517292 uniques, 517292 total prefixes). (old 517345 - new 517292)"
time="2024-02-27T16:17:55Z" level=info msg="Updated added, new serial 5"
time="2024-02-27T16:22:52Z" level=info msg="HTTP 304 Not modified for /slurm.json"
time="2024-02-27T16:22:52Z" level=info msg="HTTP 304 Not modified for http://rpki-validator-rpki-client/objects/validated"
time="2024-02-27T16:22:53Z" level=info msg="New update to old state (517292 uniques, 517292 total prefixes). (old 517345 - new 517292)"
time="2024-02-27T16:22:55Z" level=info msg="Updated added, new serial 6"

Old and New being the same values is a bit suspicious... if the expires functionality is in play I'd expect the New value to be lower at 2024-02-27T16:22:53Z

netixx commented 4 months ago

I did some checks on an example file The closest expiration is 1709054912 which is Tuesday, February 27, 2024 5:28:32 PM UTC.

 cat validated-new.json | jq '.roas[].expires' | sort -n | uniq | head -n 10
1709054912
1709058016
1709058018
1709058032
1709058152
1709059412
1709059652
1709059813
1709059831
1709059837

While the build time is "buildtime": "2024-02-27T17:04:42Z".

So nothing should expire in the next 11 minutes after the build, however I still see serial update in the meantime:

time="2024-02-27T17:02:52Z" level=info msg="HTTP 304 Not modified for /slurm.json"
2024/02/27 17:02:52 Unsolicited response received on idle HTTP channel starting with "\x1f\x8b\b\x00\x00\x00\x00\x00\x00\x03\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00"; err=<nil>
time="2024-02-27T17:02:52Z" level=info msg="HTTP 304 Not modified for http://rpki-validator-rpki-client/objects/validated"
time="2024-02-27T17:02:53Z" level=info msg="New update to old state (517312 uniques, 517312 total prefixes). (old 517365 - new 517312)"
time="2024-02-27T17:02:55Z" level=info msg="Updated added, new serial 14"
time="2024-02-27T17:07:52Z" level=info msg="HTTP 304 Not modified for /slurm.json"
time="2024-02-27T17:07:53Z" level=info msg="new cache file: Updating sha256 hash 44b481ff63399bc3bd6cd779acad03d0cd351fbd56ff0ea2b1306391812e1f87 -> cefaf622d83cf3090a70d9285265877bc902c4d25ea923fe009f6c2df087463e"
time="2024-02-27T17:07:55Z" level=info msg="New update (517327 uniques, 517327 total prefixes, 51 vaps, 2 router keys)."
time="2024-02-27T17:07:57Z" level=info msg="Updated added, new serial 15"
time="2024-02-27T17:12:52Z" level=info msg="HTTP 304 Not modified for /slurm.json"
time="2024-02-27T17:12:52Z" level=info msg="HTTP 304 Not modified for http://rpki-validator-rpki-client/objects/validated"
time="2024-02-27T17:12:53Z" level=info msg="New update to old state (517327 uniques, 517327 total prefixes). (old 517380 - new 517327)"
time="2024-02-27T17:12:55Z" level=info msg="Updated added, new serial 16"
job commented 4 months ago

yup, that is fishy!

Does rtrdump or tcpdump show any changes going out at Serial 14, 15, and 16?

netixx commented 4 months ago

I restarted stayrtr in with -loglevel debug:

time="2024-02-27T17:46:33Z" level=debug msg="Refreshing cache from http://rpki-validator-rpki-client/objects/validated"
time="2024-02-27T17:46:33Z" level=debug msg="Refreshing slurm from /slurm.json"
time="2024-02-27T17:46:33Z" level=info msg="HTTP 304 Not modified for /slurm.json"
time="2024-02-27T17:46:34Z" level=info msg="new cache file: Updating sha256 hash b1e07c8304633016d3db1423d7cc87a3df9ad0db512a7f3e2785423c4825622b -> 31e6a281b605ba3154fdbda72a011098470268ac9626e23134642da12373688f"
time="2024-02-27T17:46:37Z" level=info msg="New update (517377 uniques, 517377 total prefixes, 51 vaps, 2 router keys)."
time="2024-02-27T17:46:39Z" level=debug msg="Computed diff: added ([VRP 2607:740:45::/48 -> /48, AS396356, Flags: 1 VRP 2607:6b80:41::/48 -> /48, AS396356, Flags: 1 VRP 2607:6b80:42::/48 -> /48, AS396356, Flags: 1 VRP 2607:6b80:43::/48 -> /48, AS396356, Flags: 1 VRP 2607:6b80:44::/48 -> /48, AS396356, Flags: 1 VRP 2607:6b80:45::/48 -> /48, AS396356, Flags: 1 VRP 2607:6b80:46::/48 -> /48, AS396356, Flags: 1 VRP 2607:6b80:47::/48 -> /48, AS396356, Flags: 1 VRP 2607:6b80:48::/48 -> /48, AS396356, Flags: 1 VRP 2607:6b80:4a::/48 -> /48, AS396356, Flags: 1 VRP 2607:6b80:53::/48 -> /48, AS396356, Flags: 1 VRP 2804:1778::/35 -> /35, AS263146, Flags: 1 VRP 2804:1778:4000::/35 -> /35, AS263146, Flags: 1 VRP 2804:1778:6000::/35 -> /35, AS263146, Flags: 1 VRP 2804:1778:8000::/35 -> /35, AS263146, Flags: 1 VRP 2804:1778:a000::/35 -> /35, AS263146, Flags: 1 VRP 2804:1778:c000::/35 -> /35, AS263146, Flags: 1 VRP 2804:1778:e000::/35 -> /35, AS263146, Flags: 1 VRP 2804:1778::/34 -> /34, AS263146, Flags: 1 VRP 2804:1778:4000::/34 -> /34, AS263146, Flags: 1 VRP 2804:1778:8000::/34 -> /34, AS263146, Flags: 1 VRP 2804:1778:c000::/34 -> /34, AS263146, Flags: 1 VRP 2804:1778::/33 -> /33, AS263146, Flags: 1 VRP 2804:1778:8000::/33 -> /33, AS263146, Flags: 1 VRP 2804:282c::/32 -> /128, AS263945, Flags: 1 VRP 2804:1778::/32 -> /32, AS263146, Flags: 1 VRP 5.39.251.0/24 -> /24, AS215433, Flags: 1 VRP 45.139.211.0/24 -> /24, AS215415, Flags: 1 VRP 91.142.130.0/24 -> /24, AS212598, Flags: 1 VRP 187.86.200.0/24 -> /24, AS263146, Flags: 1 VRP 187.86.201.0/24 -> /24, AS263146, Flags: 1 VRP 187.86.202.0/24 -> /24, AS263146, Flags: 1 VRP 187.86.203.0/24 -> /24, AS263146, Flags: 1 VRP 187.86.204.0/24 -> /24, AS263146, Flags: 1 VRP 187.86.205.0/24 -> /24, AS263146, Flags: 1 VRP 187.86.206.0/24 -> /24, AS263146, Flags: 1 VRP 187.86.207.0/24 -> /24, AS263146, Flags: 1 VRP 192.228.117.0/24 -> /24, AS7018, Flags: 1 VRP 192.228.119.0/24 -> /24, AS7018, Flags: 1 VRP 187.86.200.0/23 -> /23, AS263146, Flags: 1 VRP 187.86.202.0/23 -> /23, AS263146, Flags: 1 VRP 187.86.204.0/23 -> /23, AS263146, Flags: 1 VRP 187.86.206.0/23 -> /23, AS263146, Flags: 1 VRP 138.219.180.0/22 -> /32, AS263945, Flags: 1 VRP 170.84.72.0/22 -> /32, AS263945, Flags: 1 VRP 201.216.120.0/22 -> /24, AS270305, Flags: 1 VRP 187.86.200.0/22 -> /22, AS263146, Flags: 1 VRP 187.86.204.0/22 -> /22, AS263146, Flags: 1 VRP 187.86.200.0/21 -> /21, AS263146, Flags: 1]), removed ([VRP 2607:740:45::/48 -> /48, AS13213, Flags: 0 VRP 5.39.251.0/24 -> /24, AS30938, Flags: 0 VRP 45.139.211.0/24 -> /24, AS210531, Flags: 0 VRP 199.36.120.0/24 -> /24, AS400098, Flags: 0])"
time="2024-02-27T17:46:41Z" level=info msg="Updated added, new serial 1"
time="2024-02-27T17:46:41Z" level=debug msg="Sending notifications to clients"
time="2024-02-27T17:51:33Z" level=debug msg="Refreshing cache from http://rpki-validator-rpki-client/objects/validated"
time="2024-02-27T17:51:33Z" level=debug msg="Refreshing slurm from /slurm.json"
time="2024-02-27T17:51:33Z" level=info msg="HTTP 304 Not modified for /slurm.json"
2024/02/27 17:51:33 Unsolicited response received on idle HTTP channel starting with "\x1f\x8b\b\x00\x00\x00\x00\x00\x00\x03\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00"; err=<nil>
time="2024-02-27T17:51:33Z" level=info msg="HTTP 304 Not modified for http://rpki-validator-rpki-client/objects/validated"
time="2024-02-27T17:51:34Z" level=info msg="New update to old state (517377 uniques, 517377 total prefixes). (old 517430 - new 517377)"
time="2024-02-27T17:51:36Z" level=debug msg="Computed diff: added ([]), removed ([])"
time="2024-02-27T17:51:38Z" level=info msg="Updated added, new serial 2"
time="2024-02-27T17:51:38Z" level=debug msg="Sending notifications to clients"

We can see that serial gets updated, but no actual diff are found.

(I did some tests with rtrdump, but the example I used at that point did contain an update, so it was not highlighting the right behaviour)

netixx commented 4 months ago

It looks like the sdCurrent has less entries (517430) that what we want to push (517377).

However the diff between new and old is 0 (added, removed, _ := ComputeDiff(new, s.sdCurrent, false)).

There is a possibility that the count doesn't take into account duplicates (and I guess sdCurrent does not contain duplicates), 

// func processData(vrplistjson []prefixfile.VRPJson,
if prefix.Addr().Is4() {
            countv4++
        } else {
            countv6++
        }

        key := fmt.Sprintf("%s,%d,%d", prefix, asn, v.Length)
        _, exists := filterDuplicates[key]
        if exists {
            continue
        }
        filterDuplicates[key] = struct{}{}

however, I didn't see any duplicates in my vrp file from rpki-client

❯ cat validated-new.json | jq -r '.roas[]|"\(.prefix)-\(.maxLength)-\(.asn)"' | wc -l                                                                                                                                           ⏎
  517327
❯ cat validated-new.json | jq -r '.roas[]|"\(.prefix)-\(.maxLength)-\(.asn)"' | sort | uniq | wc -l
  517327
cjeker commented 4 months ago

I don't understand how you can get a 304 error for a local file?

time="2024-02-27T16:22:52Z" level=info msg="HTTP 304 Not modified for /slurm.json"

This can only be reached if /slurm.json is fetched via HTTP.

This is what I see with: ./dist/stayrtr-0.1-218-g03532ba-linux-x86_64 -slurm /home/cjeker/go/stayrtr/emptyslurm.json -cache http://127.0.0.1/rpki.json -refresh 30 -loglevel debug -log.verbose=false -last.modified=true -protocol 1

DEBU[0153] Refreshing cache from http://127.0.0.1/rpki.json 
DEBU[0153] Refreshing slurm from /home/cjeker/go/stayrtr/emptyslurm.json 
INFO[0153] HTTP 304 Not modified for http://127.0.0.1/rpki.json 
INFO[0154] New update (518189 uniques, 518189 total prefixes, 69 vaps, 3 router keys). 
DEBU[0155] Computed diff: added (0), removed (0)        
INFO[0155] Updated added, new serial 5                  
DEBU[0155] Sending notifications to clients

So it seems that the check if the update is different is not working.

cjeker commented 4 months ago

The count only includes the roa payloads since it is countv4 + countv6. This is just stupid, calculate the count by summing up the len of the slices.

Fix for this is in #116

netixx commented 4 months ago

I don't understand how you can get a 304 error for a local file?

time="2024-02-27T16:22:52Z" level=info msg="HTTP 304 Not modified for /slurm.json"

This can only be reached if /slurm.json is fetched via HTTP.

This is what I see with: ./dist/stayrtr-0.1-218-g03532ba-linux-x86_64 -slurm /home/cjeker/go/stayrtr/emptyslurm.json -cache http://127.0.0.1/rpki.json -refresh 30 -loglevel debug -log.verbose=false -last.modified=true -protocol 1

DEBU[0153] Refreshing cache from http://127.0.0.1/rpki.json 
DEBU[0153] Refreshing slurm from /home/cjeker/go/stayrtr/emptyslurm.json 
INFO[0153] HTTP 304 Not modified for http://127.0.0.1/rpki.json 
INFO[0154] New update (518189 uniques, 518189 total prefixes, 69 vaps, 3 router keys). 
DEBU[0155] Computed diff: added (0), removed (0)        
INFO[0155] Updated added, new serial 5                  
DEBU[0155] Sending notifications to clients

So it seems that the check if the update is different is not working.

I was running a test patch that did a check for local files as well (I finally when another way, more in-line with the implementation used for the cache file).

netixx commented 4 months ago

I think the change I submitted is still valid, since I think there were actually 2 issues here: my change makes it so so that we don't always fall into the, even when the slurm file has not been updated

if cacheUpdated || slurmNotPresentOrUpdated {
err := s.updateFromNewState()

case.

The fix you submitted covers the other branch of code:

} else {
            err := s.reloadFromCurrentState()

With my change:

time="2024-02-29T12:52:00Z" level=info msg="HTTP 304 Not modified for http://rpki-validator-rpki-client/objects/validated"
time="2024-02-29T12:57:00Z" level=debug msg="Refreshing cache from http://rpki-validator-rpki-client/objects/validated"
time="2024-02-29T12:57:00Z" level=debug msg="Refreshing slurm from /slurm.json"
time="2024-02-29T12:57:00Z" level=error msg="Slurm: File /slurm.json is identical to the previous version"
time="2024-02-29T12:57:00Z" level=info msg="HTTP 304 Not modified for http://rpki-validator-rpki-client/objects/validated"
time="2024-02-29T13:02:00Z" level=debug msg="Refreshing cache from http://rpki-validator-rpki-client/objects/validated"
time="2024-02-29T13:02:00Z" level=debug msg="Refreshing slurm from /slurm.json"
time="2024-02-29T13:02:00Z" level=error msg="Slurm: File /slurm.json is identical to the previous version"
2024/02/29 13:02:00 Unsolicited response received on idle HTTP channel starting with "\x1f\x8b\b\x00\x00\x00\x00\x00\x00\x03\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00"; err=<nil>
time="2024-02-29T13:02:00Z" level=info msg="HTTP 304 Not modified for http://rpki-validator-rpki-client/objects/validated"
time="2024-02-29T13:07:00Z" level=debug msg="Refreshing cache from http://rpki-validator-rpki-client/objects/validated"
time="2024-02-29T13:07:00Z" level=debug msg="Refreshing slurm from /slurm.json"
time="2024-02-29T13:07:00Z" level=error msg="Slurm: File /slurm.json is identical to the previous version"
time="2024-02-29T13:07:02Z" level=info msg="new cache file: Updating sha256 hash b22742b5e8a6f11fb53aba6df70bf48e6526a0b0e7112b5f03cb5903ee724b86 -> 57c62a46013ef858c916385e09e97101dab7f706ca11fa3e182b11cffce1ce1e"
time="2024-02-29T13:07:04Z" level=info msg="New update (518065 uniques, 518116 total prefixes, 49 vaps, 2 router keys)."
time="2024-02-29T13:07:06Z" level=debug msg="Computed diff: added ([VRP 2a0e:f600::/48 -> /48, AS60781, Flags: 1 VRP 154.205.226.0/24 -> /24, AS44559, Flags: 1 VRP 154.205.227.0/24 -> /24, AS44559, Flags: 1 VRP 154.205.228.0/24 -> /24, AS44559, Flags: 1 VRP 154.205.229.0/24 -> /24, AS44559, Flags: 1 VRP 154.205.230.0/24 -> /24, AS44559, Flags: 1 VRP 154.205.231.0/24 -> /24, AS44559, Flags: 1 VRP 154.205.232.0/24 -> /24, AS44559, Flags: 1 VRP 154.205.233.0/24 -> /24, AS44559, Flags: 1 VRP 154.205.234.0/24 -> /24, AS44559, Flags: 1 VRP 154.205.235.0/24 -> /24, AS44559, Flags: 1 VRP 154.205.236.0/24 -> /24, AS44559, Flags: 1 VRP 154.205.237.0/24 -> /24, AS44559, Flags: 1 VRP 154.205.238.0/24 -> /24, AS44559, Flags: 1 VRP 199.36.120.0/24 -> /24, AS400098, Flags: 1]), removed ([VRP 43.247.120.0/24 -> /24, AS132165, Flags: 0 VRP 43.247.121.0/24 -> /24, AS132165, Flags: 0 VRP 43.247.122.0/24 -> /24, AS132165, Flags: 0 VRP 43.247.123.0/24 -> /24, AS132165, Flags: 0])"
time="2024-02-29T13:07:06Z" level=info msg="Updated added, new serial 7"
time="2024-02-29T13:07:06Z" level=debug msg="Sending notifications to clients"
time="2024-02-29T13:12:00Z" level=debug msg="Refreshing cache from http://rpki-validator-rpki-client/objects/validated"
time="2024-02-29T13:12:00Z" level=debug msg="Refreshing slurm from /slurm.json"
time="2024-02-29T13:12:00Z" level=error msg="Slurm: File /slurm.json is identical to the previous version"
2024/02/29 13:12:00 Unsolicited response received on idle HTTP channel starting with "\x1f\x8b\b\x00\x00\x00\x00\x00\x00\x03\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00"; err=<nil>
time="2024-02-29T13:12:00Z" level=info msg="HTTP 304 Not modified for http://rpki-validator-rpki-client/objects/validated"
time="2024-02-29T13:12:01Z" level=info msg="New update to old state (518061 uniques, 518112 total prefixes). (old 518116 - new 518112)"
time="2024-02-29T13:12:03Z" level=debug msg="Computed diff: added ([]), removed ([VRP 2804:6bc::/32 -> /48, AS53078, Flags: 0 VRP 170.80.252.0/22 -> /24, AS53078, Flags: 0 VRP 186.193.16.0/20 -> /24, AS53078, Flags: 0 VRP 187.94.208.0/20 -> /24, AS53078, Flags: 0])"
time="2024-02-29T13:12:04Z" level=info msg="Updated added, new serial 8"
time="2024-02-29T13:12:04Z" level=debug msg="Sending notifications to clients"
time="2024-02-29T13:17:00Z" level=debug msg="Refreshing cache from http://rpki-validator-rpki-client/objects/validated"
time="2024-02-29T13:17:00Z" level=debug msg="Refreshing slurm from /slurm.json"
time="2024-02-29T13:17:00Z" level=error msg="Slurm: File /slurm.json is identical to the previous version"
2024/02/29 13:17:00 Unsolicited response received on idle HTTP channel starting with "\x1f\x8b\b\x00\x00\x00\x00\x00\x00\x03\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00"; err=<nil>
time="2024-02-29T13:17:00Z" level=info msg="HTTP 304 Not modified for http://rpki-validator-rpki-client/objects/validated"

Without

time="2024-02-29T13:38:21Z" level=debug msg="Refreshing cache from http://rpki-validator-rpki-client/objects/validated"
time="2024-02-29T13:38:21Z" level=debug msg="Refreshing slurm from /slurm.json"
2024/02/29 13:38:21 Unsolicited response received on idle HTTP channel starting with "\x1f\x8b\b\x00\x00\x00\x00\x00\x00\x03\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00"; err=<nil>
time="2024-02-29T13:38:21Z" level=info msg="HTTP 304 Not modified for http://rpki-validator-rpki-client/objects/validated"
time="2024-02-29T13:38:22Z" level=info msg="New update (518079 uniques, 518130 total prefixes, 49 vaps, 2 router keys)."
time="2024-02-29T13:38:24Z" level=debug msg="Computed diff: added ([]), removed ([])"
time="2024-02-29T13:38:26Z" level=info msg="Updated added, new serial 1"
time="2024-02-29T13:38:26Z" level=debug msg="Sending notifications to clients"
time="2024-02-29T13:43:21Z" level=debug msg="Refreshing cache from http://rpki-validator-rpki-client/objects/validated"
time="2024-02-29T13:43:21Z" level=debug msg="Refreshing slurm from /slurm.json"
time="2024-02-29T13:43:21Z" level=info msg="HTTP 304 Not modified for http://rpki-validator-rpki-client/objects/validated"
time="2024-02-29T13:43:22Z" level=info msg="New update (518078 uniques, 518129 total prefixes, 49 vaps, 2 router keys)."
time="2024-02-29T13:43:24Z" level=debug msg="Computed diff: added ([]), removed ([VRP 154.80.9.0/24 -> /24, AS45669, Flags: 0])"
time="2024-02-29T13:43:25Z" level=info msg="Updated added, new serial 2"
time="2024-02-29T13:43:25Z" level=debug msg="Sending notifications to clients"
time="2024-02-29T13:48:21Z" level=debug msg="Refreshing cache from http://rpki-validator-rpki-client/objects/validated"
time="2024-02-29T13:48:21Z" level=debug msg="Refreshing slurm from /slurm.json"
time="2024-02-29T13:48:22Z" level=info msg="new cache file: Updating sha256 hash e741f9bb354b4d0adc3b319720b914f294eb4cac8e32a5ccfef66b381b2b2be3 -> 3023d1c8cf12549e12e7a1a1d28e0e02f4a021ebc49a50f7d98c9113851e561f"
time="2024-02-29T13:48:25Z" level=info msg="New update (518090 uniques, 518141 total prefixes, 49 vaps, 2 router keys)."
time="2024-02-29T13:48:27Z" level=debug msg="Computed diff: added ([VRP 2402:5380:e000::/40 -> /48, AS63980, Flags: 1 VRP 2402:5380:e100::/40 -> /48, AS63980, Flags: 1 VRP 2402:5380:e200::/40 -> /48, AS63980, Flags: 1 VRP 2402:5380:e300::/40 -> /48, AS63980, Flags: 1 VRP 2402:5380:e400::/40 -> /48, AS63980, Flags: 1 VRP 2402:5380:e500::/40 -> /48, AS63980, Flags: 1 VRP 2402:5380:e600::/40 -> /48, AS63980, Flags: 1 VRP 2402:5380:e700::/40 -> /48, AS63980, Flags: 1 VRP 2402:5380:e800::/40 -> /48, AS63980, Flags: 1 VRP 2402:5380:e900::/40 -> /48, AS63980, Flags: 1 VRP 2402:5380:ea00::/40 -> /48, AS63980, Flags: 1 VRP 2402:5380:eb00::/40 -> /48, AS63980, Flags: 1 VRP 2402:5380:ec00::/40 -> /48, AS63980, Flags: 1 VRP 2402:5380:ed00::/40 -> /48, AS63980, Flags: 1 VRP 2402:5380:ee00::/40 -> /48, AS63980, Flags: 1 VRP 84.247.105.0/24 -> /24, AS3257, Flags: 1 VRP 103.75.21.0/24 -> /24, AS132429, Flags: 1 VRP 192.165.152.0/24 -> /24, AS49769, Flags: 1 VRP 192.165.153.0/24 -> /24, AS49769, Flags: 1 VRP 192.165.154.0/24 -> /24, AS49769, Flags: 1 VRP 192.165.155.0/24 -> /24, AS49769, Flags: 1 VRP 193.235.2.0/24 -> /24, AS49769, Flags: 1 VRP 193.235.3.0/24 -> /24, AS49769, Flags: 1 VRP 217.156.108.0/23 -> /23, AS61002, Flags: 1 VRP 178.78.128.0/18 -> /24, AS44395, Flags: 1]), removed ([VRP 2605:9cc0:f014::/48 -> /48, AS16509, Flags: 0 VRP 2605:9cc0:f016::/48 -> /48, AS16509, Flags: 0 VRP 2605:9cc0:f018::/48 -> /48, AS16509, Flags: 0 VRP 2605:9cc0:f01c::/48 -> /48, AS16509, Flags: 0 VRP 2605:9cc0:f01e::/48 -> /48, AS16509, Flags: 0 VRP 2605:9cc0:f020::/48 -> /48, AS16509, Flags: 0 VRP 84.247.105.0/24 -> /24, AS174, Flags: 0 VRP 103.75.21.0/24 -> /24, AS45355, Flags: 0 VRP 154.80.10.0/24 -> /24, AS45669, Flags: 0 VRP 154.80.69.0/24 -> /24, AS45669, Flags: 0 VRP 188.162.128.0/23 -> /23, AS31163, Flags: 0 VRP 217.156.108.0/23 -> /23, AS48749, Flags: 0 VRP 178.78.184.0/21 -> /24, AS8932, Flags: 0])"
time="2024-02-29T13:48:28Z" level=info msg="Updated added, new serial 3"
time="2024-02-29T13:48:28Z" level=debug msg="Sending notifications to clients"
time="2024-02-29T13:53:21Z" level=debug msg="Refreshing cache from http://rpki-validator-rpki-client/objects/validated"
time="2024-02-29T13:53:21Z" level=debug msg="Refreshing slurm from /slurm.json"
2024/02/29 13:53:21 Unsolicited response received on idle HTTP channel starting with "\x1f\x8b\b\x00\x00\x00\x00\x00\x00\x03\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00"; err=<nil>
time="2024-02-29T13:53:21Z" level=info msg="HTTP 304 Not modified for http://rpki-validator-rpki-client/objects/validated"
time="2024-02-29T13:53:22Z" level=info msg="New update (518090 uniques, 518141 total prefixes, 49 vaps, 2 router keys)."
time="2024-02-29T13:53:24Z" level=debug msg="Computed diff: added ([]), removed ([])"
cjeker commented 4 months ago

Yes, I agree both your PR (#115) and my PRs (#116 and #117) need to be merged to properly fix this bug.

netixx commented 2 months ago

I believe all that's required is done.

Thank you for all the work :)