Long-running tasks cause "NetworkError when attempting to fetch resource." in generic-worker livelog feature

[gabrielbusta]

Bug description

We are using the livelog feature on generic-worker to monitor long running tasks. The live logging works for some time (maybe around 24 hours.) After a while we start seeing "NetworkError when attempting to fetch resource." in the log view.

To reproduce

1. Go to a long running task that has been executing for a while
2. Click on "View Live Log"
3. See "NetworkError when attempting to fetch resource." error

Expected behavior

The livelog should stream logs for the duration of the task.

Taskcluster version

55.3.0

generic-worker version

55.1.1

Screenshot

Platform

Linux (amd64)

Additional context

mozilla/translations#200

[lotas]

Thanks Gabriel for submitting this issue.

When I go now to open that initial link public/logs/live.log it now properly redirects, since it points to the existing artifact already.

I'm not too familiar with websocket proxy internals, but it seems like session tunnel was closed for some reason (which is possible over long period of time), or the session token expired.

Auth service issues websocktunnel tokens which live up to 96hr
And it seems like this worker was running this task for somewhere around 4-5 days.

So there are two possible directions to address this issue:

1. we would patch websocktunnel to take care of expiration aspect of those tokens, and let it refresh the token. This would require releasing new workers/imagesets.
2. we allow larger expiration dates for the tokens in auth service. This would be the quickest fix, but we need to check what would be the implications of letting those tokens live longer

I don't immediately see why having longer lived tokens would be bad security wise, they don't seem to have much permissions, only allow workers to connect to the tunnel ? @petemoore what do you think?

[gabrielbusta]

Thanks for taking a look.

Yeah, I should have mentioned we see the logs once the task is finished.

The auth service websocktunnel token expiring certainly seems to be the underlying issue here.

The services description says:

The token is valid for a limited time (on the scale of hours). Callers should refresh it before expiration.

Could the generic-worker livelog feature refresh its own token before it expires?

[petemoore]

I don't know too much about websocktunnel, but this comment seems to suggest that token refreshing should already be built in. I'm just not sure how, since this is the only place I see where a token is fetched:

taskcluster/workers/generic-worker/expose/wst.go

Lines 78 to 79 in 15284ce

	// note that we ignore the "expires" value, as we simply generate a new
	// token each time we need one

[djmitche]

It would be good to know what the underlying network error is that is being describe as a "network error" in the UI, and also to look at the WST logs at that time. Also, does this issue occur any time you try to load the logs after ~24 hours, or is this a single tab actively tailing the live-logs for 24 hours and failing after that time?

The token that the generic-worker exposer gets from auth.websocktunnelToken is for the connection from the worker to the websocktunnel server. A new token is fetched before each such connection, and that connection then stays open for however long the network between those two endpoints allows. When that connection fails, generic-worker should reconnect and pick up where it left off. The token is only consulted at the beginning of that connection, which should be only a few seconds after the token was issued.

There's a lot of network and tunnels to consider here, so narrowing down what is going wrong is a good place to start.

[aerickson]

Where are the WST logs written?

[djmitche]

I think they're just the stdout from the websocktunnel process -- wherever that goes. I don't remember if debug logging is enabled by default.

That wasn't necessarily the data I was suggesting gathering!

[marco-c]

Is there a workaround we can employ in the meantime to get access to the live logs?

[marco-c]

Looking at mozilla/translations#200 (comment), it looks like the error we see is 504.

[petemoore]

Looking at mozilla/firefox-translations-training#200 (comment), it looks like the error we see is 504.

@lotas @djmitche Any ideas here?

[djmitche]

Nope, same questions remain.

[marco-c]

See also #6685.

[lotas]

we also realized today that some of those issues might be related to the fact that websocktunnel container is being restarted sometimes! which might result in dropped connections, and if clients do not auto-reconnect, those live logs would be gone

Here are restarts for the past 30d:

[bhearsum]

I noticed this happen with a task that was running earlier today. @lotas had a look at the websocktunnel GCP logs and it does look like the service was restarted around the time the log stopped working, which seems to lend some evidence to the theory above.

@lotas also noticed that the restarts were caused because the pods requested too much memory.

AIUI, this means there's probably two things we might want to do:

• Ensure that workers reconnect if their websocktunnel connection is closed
• Tweak deployment parameters to reduce or eliminate restarts of the service during normal operation
• Investigate and fix and memory leaks in websocktunnel.

[lotas]

I think it could have been a deployment configuration thingy.. Before the holidays I increased memory limits, so the pod wouldn't be killed, and it looks like it worked just fine, pod was not killed so frequently! In fact, only once

It seems like CPU usage was going up, so we likely would have to restart it periodically still (or fix cpu/mem leaks)