The same piece that saves the UUID should also save the server commit as represented in https://github.com/m-lab/go/blob/master/prometheusx/prom.go#L31

There was a pid leak detected by mlab3.fln01

https://github.com/m-lab/ops-tracker/issues/1204

After investigation of the log, the pid leak was caused by scamper after scamper-daeon failed:

==================
360WARNING: DATA RACE
361Write at 0x00000109b118 by goroutine 18:
362  github.com/m-lab/traceroute-caller.TestMainWithConnectionListener()
363      /home/travis/gopath/src/github.com/m-lab/traceroute-caller/caller_test.go:52 +0x522
364  testing.tRunner()
365      /home/travis/.gimme/versions/go1.11.13.linux.amd64/src/testing/testing.go:827 +0x162
366
367Previous read at 0x00000109b118 by goroutine 39:
368  github.com/m-lab/traceroute-caller.main.func1()
369      /home/travis/gopath/src/github.com/m-lab/traceroute-caller/caller.go:76 +0x70
370
371Goroutine 18 (running) created at:
372  testing.(*T).Run()
373      /home/travis/.gimme/versions/go1.11.13.linux.amd64/src/testing/testing.go:878 +0x659
374  testing.runTests.func1()
375      /home/travis/.gimme/versions/go1.11.13.linux.amd64/src/testing/testing.go:1119 +0xa8
376  testing.tRunner()
377      /home/travis/.gimme/versions/go1.11.13.linux.amd64/src/testing/testing.go:827 +0x162
378  testing.runTests()
379      /home/travis/.gimme/versions/go1.11.13.linux.amd64/src/testing/testing.go:1117 +0x4ee
380  testing.(*M).Run()
381      /home/travis/.gimme/versions/go1.11.13.linux.amd64/src/testing/testing.go:1034 +0x2ee
382  main.main()
383      _testmain.go:46 +0x221
384
385Goroutine 39 (finished) created at:
386  github.com/m-lab/traceroute-caller.main()
387      /home/travis/gopath/src/github.com/m-lab/traceroute-caller/caller.go:74 +0x978
388  github.com/m-lab/traceroute-caller.TestMain()
389      /home/travis/gopath/src/github.com/m-lab/traceroute-caller/caller_test.go:37 +0x301
390  testing.tRunner()
391      /home/travis/.gimme/versions/go1.11.13.linux.amd64/src/testing/testing.go:827 +0x162
392==================
393

The two tests in caller_test.go have race conditions around the global cancel() function.

Now it is about 97%

This is just a few suggestions for improving readability for the Tracer and cachedTest code. It isn't fully fleshed out, so a little more thought is required.

The fact that Trace() and CreateCacheTrace both write files is confusing. It seems like it would be much clearer if there was a function that generates a trace, and a function that creates a file.

If that were the case, then you could replace the channel with a sync.Once, and have a GetData(ip string) that uses once.Do() to create the trace in the cache entry. The you would get the cache entry, call GetData() on the cache entry, then call the function to create the file.

There is some question as to whether we should be saving the original UUID, since that reduces anonymity, but ideally, only the IP address would be needed to create a trace, and only the trace data (without any connection metadata or original UUID) would be stored, which would simplify things further. The ip address would be passed to Trace, and the Connection would only be passed to SaveTrace.

So:
type Tracer interface {
// Just creates the body, not the metadata header.
Trace(ip string) string
}

// Creates the header, appends the body, saves the file.
func SaveTrace(conn Connection, t time.Time, data string) {
...
}

type cachedTest struct {
timeStamp time.Time
uuid string // If we really need the original uuid.
data string
once sync.Once
}

func (ct *cachedTest) getTest(t Tracer, ip string, uuid string) (string, string) {
once.Do(func() {
ct.uuid = uuid // kinda ugly - better ways to do this.
ct.data = t.Trace(ip)
})

return ct.data

}

The frequency of scamper segfaults in staging is still very high. The consequence of this is the restart of traceroute container. The restarts result in a noisy summary of available containers relative to pre-release of v0.3.3. That alone might be okay but about 25% of the host containers not monitorable, suggesting the highest rate of segfaults in the host deployment.

https://pantheon.corp.google.com/storage/browser/_details/archive-mlab-oti/ndt/traceroute/2019/11/01/20191101T020014.044139Z-traceroute-mlab3-lax03-ndt.tgz?project=mlab-oti&organizationId=433637338589

All tests in this tarball is <1k bytes.

A typical one is like:

======================

{"UUID":"ndt-9fw2l_1572433802_000000000001C6A1","TracerouteCallerVersion":"bc092be","CachedResult":true,"CachedUUID":"ndt-9fw2l_1572433802_000000000001C6A3"}
{"type":"cycle-start", "list_name":"/tmp/scamperctrl:16626", "id":1, "hostname":"ndt-9fw2l", "start_time":1572739620}
{"type":"tracelb", "version":"0.1", "userid":0, "method":"icmp-echo", "src":"::ffff:173.205.3.101", "dst":"::ffff:68.190.243.205", "start":{"sec":1572739620, "usec":959242, "ftime":"2019-11-03 00:07:00"}, "probe_size":60, "firsthop":1, "attempts":3, "confidence":95, "tos":0, "gaplimit":3, "wait_timeout":5, "wait_probe":250, "probec":0, "probec_max":3000, "nodec":0, "linkc":0}
{"type":"cycle-stop", "list_name":"/tmp/scamperctrl:16626", "id":1, "hostname":"ndt-9fw2l", "stop_time":1572739620}

a good number scamper segfaults on mlab2.lga0t. Is this expected? Log messages look like: scamper[5963]: segfault at 0 ip 0000558ffcd236f0 sp 00007ffed36cd0f8 error 4 in scamper[558ffcd14000+92000]

Traceroutes that take too long are never going to return. But we never stop waiting.

I made two changes - adding a metric for trace latency, and changing panics to errors.

In testing on sandbox, I noticed that roughly 90% of traces are timing out:

TYPE trace_time_seconds histogram

trace_time_seconds_bucket{outcome="error",le="10"} 0
trace_time_seconds_bucket{outcome="error",le="21.5"} 0
trace_time_seconds_bucket{outcome="error",le="46.4"} 0
trace_time_seconds_bucket{outcome="error",le="100"} 0
trace_time_seconds_bucket{outcome="error",le="215"} 0
trace_time_seconds_bucket{outcome="error",le="464"} 90
trace_time_seconds_bucket{outcome="error",le="1000"} 90
trace_time_seconds_count{outcome="error"} 90
trace_time_seconds_bucket{outcome="success",le="10"} 1
trace_time_seconds_bucket{outcome="success",le="21.5"} 2
trace_time_seconds_bucket{outcome="success",le="46.4"} 2
trace_time_seconds_bucket{outcome="success",le="100"} 3
trace_time_seconds_bucket{outcome="success",le="215"} 8
trace_time_seconds_bucket{outcome="success",le="464"} 12
trace_time_seconds_bucket{outcome="success",le="1000"} 12
trace_time_seconds_count{outcome="success"} 12

I'm running again after fixing a bug in error handling, but I expect that we have been overlooking this problem for some time, and unaware of it because traceroute parsing has also been having a lot of problems.

It is designed to be used like:

if !cache.Has(ip) {
  cache.Add(ip)
  Trace(ip)
}

but this check-then-add pattern is not threadsafe. Instead, we should use an unconditional Add that returns true if the item was not previously in the cache. Then the usage would be:

if cache.Add(ip) {
  Trace(ip)
}

which (as long as Add is mutex-protected) is threadsafe.

I compare the site traffic in 2019/05 (Paris Tracerout) vs. 2019/08 (scamper):

mlab3-den04: 609300, 63800
mlab3-beg01: 660600, 91800
mlab2-mil02: 465900, 149437
mlab2-sea06: 260300, 21000

One possible reason is that scamper test took longer time to complete compared to PT. So the 60 seconds timeout will make most of scamper test fail in the middle.

Attached BigQuery used:

#legacySQL
SELECT

COUNT(TestTime) AS num

FROM (

SELECT TestTime

FROM [mlab-oti.batch.traceroute]

WHERE
DATE(_PARTITIONTIME) BETWEEN DATE("2019-05-01") AND DATE("2019-06-01")
AND uuid = ""
AND Parseinfo.TaskFileName CONTAINS "mlab2-sea06"

)

====================

#legacySQL
SELECT

COUNT(uuid) AS num

FROM (

SELECT uuid

FROM [mlab-oti.batch.traceroute]

WHERE
  DATE(_PARTITIONTIME) BETWEEN DATE("2019-08-01") AND DATE("2019-09-01")
  AND Parseinfo.TaskFileName CONTAINS "mlab2-sea06"
)

please check traceroute for a goroutine and possible process leak -- https://grafana.mlab-sandbox.measurementlab.net/d/hU5aYvaWz/k8s-site-overview?orgId=1&var-datasource=Platform%20Cluster%20(mlab-sandbox)&var-site=lga0t&var-node=mlab3&var-pod=ndt&from=now-24h&to=now&refresh=1m
(bottom two panels)

It is only there for debugging purposes in this initial deployment.

As written, ipcache does not cache the results, which means that UUIDs corresponding to flows with the IP in the cache don't get any data. Instead, the system should cache the result and provide the cached result when a redundant request comes in.

It should also add a metadata field or fields to indicate that (a) the result was retrieved from the cache and (b) the UUID of the connection that initially populated the cache.

Ideally one which does not also require the development tools to be installed.

In particular, not every successful NDT test has a corresponding traceroute. We should understand why this is AND/OR make it so that no connections are missed.

2 | 2020-01-26 | 8539584 |  
-- | -- | --
3 | 2020-01-25 | 8802175 |  
4 | 2020-01-24 | 8804368 |  
5 | 2020-01-23 | 8989835 |  
6 | 2020-01-22 | 9547450 |  
7 | 2020-01-21 | 9553054 |  
8 | 2020-01-20 | 9684823 |  
9 | 2020-01-19 | 9787798 |  
10 | 2020-01-18 | 10059376 |  
11 | 2020-01-17 | 9847430 |  
12 | 2020-01-16 | 10236158 |  
13 | 2020-01-15 | 10198442 |  
14 | 2020-01-14 | 10056294 |  
15 | 2020-01-13 | 10208497

Many changes have been made since release 0.6.0. We should identify all bug fixes since then, and apply them to a new branch to update TRC 2.0.

IP addresses gotten from connectionpoller don't serialize to strings for use on the command-line in the same way that IP addresses from connectionlistener do when used in https://github.com/m-lab/traceroute-caller/blob/master/tracer/scamper.go#L101 . We should fix the line in scamper.go or fix connectionpoller or both.

Move the code out of ETL parser eventually.

No matter what the return status was.

This is from ETL parser log:

JSON parsing failed with error unexpected end of JSON input for 2019/10/31/ndt-9sng7/20191031T205313Z_2600:3c02::17:d802_16b47e.jsonl

pt.go:531: JSON parsing failed with error unexpected end of JSON input for 2019/10/29/ndt-9sng7/20191029T174213Z_2600:3c02::17:d802_162087.jsonl

pt.go:531: JSON parsing failed with error unexpected end of JSON input for 2019/10/31/ndt-vg4pn/20191031T212206Z_2600:3c02::17:d802_174d51.jsonl

Looking at prometheus metrics for process_open_fds for traceroute that there is a fd leak. See image below:

After a rollout on the 16th, the fd count has steadily increased until machine reboots.

Only lga0* nodes are shown for convenience. The pattern is global. Originally started on ~Nov 8th in staging and Nov 14th in production.

sum by(machine, container, deployment) (process_open_fds{machine=~".*", container=~"traceroute"})

Both traceroute-caller and etl implement the same logic to compute IDs for hops in traceroute and hopannotation1 data.

The code in etl should be cross-referenced from traceroute-caller.
https://github.com/m-lab/etl/blob/6b71af189cc7da413cce59f798ca3b3377832c8c/parser/parser.go#L87

For current IPCache implementation, there are other traces that might be waiting for a going on one.

If that trace failed with an error message (scamper failure, timeout failure, etc), there was no proper handling through current channel implementation (no error message sent back).

The current sample output using "cat" is:

{"schema_version":""1"","uuid":""ndt-cbppg_1589996412_000000000000A94A"","testtime":"0001-01-01T00:00:00Z","start_time":1590086579,"stop_time":1590086579,"scamper_version":""0.1"","serverIP":""4.14.159.101"","clientIP":""4.14.159.86"","probe_size":44,"probec":1,"hop":null,"cached_result":true,"cached_uuid":""ndt-cbppg_1589996412_000000000000A689"","traceroutecaller_commit":""608d1a7""}

The code in tracer/scamper.go use

json.Marshal
ioutil.WriteFile

To create the .json file

Tried out scamper mode on sandbox ndt pods. All traces are now failing:

2021/06/27 11:35:39 scamper.go:132: Trace failed in context 0xc000294540 (error: exit status 255: scamper -I "tracelb -P icmp-echo -q 3 -W 25 -O ptr 2600:3c02:e000:185:0:242:ac11:2" -o- -O json)

The following Bigquery query discovers 300+ times traceroute-caller was called multiple times for a given UUID:

with 
uuids as (
  SELECT COUNT(*) as count, uuid, Parseinfo.TaskFileName as fname
  FROM `mlab-staging.batch.traceroute`
  group by uuid, Parseinfo.TaskFileName
)
select uuid, fname from uuids where count > 1 and uuid != ""

This seems pretty obviously incorrect, and we should fix it. Note that the UUID appearing multiple times here is in fact correct - it's the same connection (and so the same UUID) causing multiple calls to scamper's traceroute system.

Builds of fast-mda-traceroute have failed since 2022-12-16.

# RUN pip3 install --no-binary pycaracal --no-cache-dir --verbose fast-mda-traceroute==0.1.10

Which concludes with errors like below, but the resolution is unknown.

2022-12-17T23:45:42Z #25 173.1 pip._internal.exceptions.InstallationError: Could not build wheels for pycaracal which use PEP 517 and cannot be installed directly

The build step can be enabled once it is working as intended again and we intend to include fast mda in TRC.

The traceroute-caller service should create output directories on startup so archiving processes like pusher or jostler have access to these directories. If traceroute-caller creates the directory it should guarantee that it has write permission and the archiving processes can start minimal races.

This functionality is preferred to externally managing the creation of these directories or waiting until traceroute-caller runs its first trace and writes the output. The timing of this is not always guaranteed.

It looks like traceroute-caller, at least with scamper-daemon, has limited capacity, and, even with -p 1000, seem to get slower and slower if there are too many requests coming in.

If we limit the number of concurrent traces, it will improve latency, and likely have little or no effect on throughput.

These dashboard panels for gru01 basically shows that, for current deployment, things work ok until about 60 to 70 concurrent traces, then rapidly start to get much worse. This happen at around 15 trace per minute, which is much too slow for our busier sites.

So, perhaps we should limit the number of concurrent traces we allow to start. We should evaluate the practical throughput with the pending deployment, and set a corresponding threshold for rejecting new traceroute requests. It appears that the limit can be fairly conservative - perhaps 30 or 40, as the throughput is quite insensitive to the concurrency.

KR place holder

When tracelb is run with bad parameters we see "do_scamperread_line: command not accepted" in the logs. But we apparently don't check any status.

pt.go:168: Invalid test gs://archive-mlab-staging/ndt/traceroute/2019/12/15/20191215T080346.438322Z-traceroute-mlab4-nuq07-ndt.tgz 2019/12/15/20191215T063922Z_ndt-qv4lg_1575424974_0000000000002F72.jsonl

===========================

Test seems truncated:

{"UUID":"ndt-78s2l_1575426876_0000000000001F25","TracerouteCallerVersion":"966aa47","CachedResult":false,"CachedUUID":""}
{"type":"cycle-start", "list_name":"/tmp/scamperctrl:1566", "id":1, "hostname":"ndt-78s2l", "start_time":1576352716}

How long does it take for the process of running a traceroute to run, from end to end?

How many traceroutes have been performed?

How many times has the scamper client exited with a non-zero error code?

We should have metrics for all of these.

There used to be 60s timeout in python version traceroute caller for Legacy Paris Traceroute binary.

We might bring it back with 2 to 5 minutes timeout in this Go implementation.

The scamper deployment, at least on staging, needs a node selector to prevent it trying to run on the k8s-prometheus node.

scamper-tcf48 1/2 CrashLoopBackOff 240 20h 10.0.0.20 k8s-prometheus

number of success/failure, duration, etc.