generic-worker: Interactive username testdroid does not match task user task_1562746981 from next-task-user.json file
Categories
(Taskcluster :: Workers, defect)
Tracking
(Not tracked)
People
(Reporter: egao, Unassigned)
References
Details
Attachments
(1 file)
|
20.75 KB,
text/plain
|
Details |
Bitbar reported issues with the generic-worker 15.1.0 installed on one of the windows10-aarch64 machines.
This machine previously ran either generic-worker 13.0.2 or 14.1.1, and was upgraded using OCC script to 15.1.0.
The things I have asked Bitbar to try:
- remove
current-task-user.json - remove
next-task-user.json - remove Generic Worker service
- possibly removed
HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows NT\CurrentVersion\Winlogon\DefaultUserName - possibly removed
HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows NT\CurrentVersion\Winlogon\DefaultPassword
The machine, after rebooting continues to show this error log:
2019/07/10 17:50:37 Making system call GetProfilesDirectoryW with args: [0 18CD8478]
2019/07/10 17:50:37 Result: 0 7FFFFFF7 The data area passed to a system call is too small.
2019/07/10 17:50:37 Making system call GetProfilesDirectoryW with args: [18CF69A0 18CD8478]
2019/07/10 17:50:37 Result: 1 7FFFFFF7 The operation completed successfully.
2019/07/10 17:50:37 Making system call GetProfilesDirectoryW with args: [0 18D58FB8]
2019/07/10 17:50:37 Result: 0 7FFFFFF7 The data area passed to a system call is too small.
2019/07/10 17:50:37 Making system call GetProfilesDirectoryW with args: [18CF6F80 18D58FB8]
2019/07/10 17:50:37 Result: 1 7FFFFFF7 The operation completed successfully.
2019/07/10 17:50:37 Loading generic-worker config file 'C:\generic-worker\generic-worker.config'...
2019/07/10 17:50:37 Config: {
"accessToken": "*************",
"authBaseURL": "",
"availabilityZone": "",
"cachesDir": "caches",
"certificate": "",
"checkForNewDeploymentEverySecs": 1800,
"cleanUpTaskDirs": true,
"clientId": "mozilla-auth0/google-oauth2|115908155405501488952/",
"deploymentId": "",
"disableReboots": false,
"downloadsDir": "downloads",
"ed25519SigningKeyLocation": "C:\\generic-worker\\ed25519.key",
"idleTimeoutSecs": 0,
"instanceId": "",
"instanceType": "",
"livelogCertificate": "",
"livelogExecutable": "livelog",
"livelogGETPort": 60023,
"livelogKey": "",
"livelogPUTPort": 60022,
"livelogSecret": "*************",
"numberOfTasksToRun": 0,
"privateIP": "",
"provisionerBaseURL": "",
"provisionerId": "bitbar",
"publicIP": "1.1.1.1",
"purgeCacheBaseURL": "",
"queueBaseURL": "",
"region": "",
"requiredDiskSpaceMegabytes": 10240,
"rootURL": "https://taskcluster.net",
"runAfterUserCreation": "",
"runTasksAsCurrentUser": false,
"secretsBaseURL": "",
"sentryProject": "",
"shutdownMachineOnIdle": false,
"shutdownMachineOnInternalError": false,
"subdomain": "taskcluster-worker.net",
"taskclusterProxyExecutable": "taskcluster-proxy",
"taskclusterProxyPort": 80,
"tasksDir": "C:\\tasks",
"workerGroup": "bitbar-sc",
"workerId": "t-lenovoyogac630-022",
"workerType": "gecko-t-win64-aarch64-laptop",
"workerTypeMetadata": {
"config": {
"deploymentId": ""
},
"generic-worker": {
"engine": "multiuser",
"go-arch": "386",
"go-os": "windows",
"go-version": "go1.10.8",
"release": "https://github.com/taskcluster/generic-worker/releases/tag/v15.1.0",
"revision": "778862340976f46be65f3c7a5f2c94abbc9b7d35",
"source": "https://github.com/taskcluster/generic-worker/commits/778862340976f46be65f3c7a5f2c94abbc9b7d35",
"version": "15.1.0"
}
},
"wstAudience": "",
"wstServerURL": ""
2019/07/10 17:54:09 Making system call WTSQueryUserToken with args: [1 18A80EA8]
2019/07/10 17:54:09 Result: 0 0 An attempt was made to reference a token that does not exist.
2019/07/10 17:54:09 Making system call WTSGetActiveConsoleSessionId with args: []
2019/07/10 17:54:09 Result: 1 18D1D908 The operation completed successfully.
2019/07/10 17:54:09 Making system call WTSQueryUserToken with args: [1 18A80EA8]
2019/07/10 17:54:09 Result: 0 0 An attempt was made to reference a token that does not exist.
2019/07/10 17:54:09 Making system call WTSGetActiveConsoleSessionId with args: []
2019/07/10 17:54:09 Result: 1 18D1D908 The operation completed successfully.
2019/07/10 17:54:09 Making system call WTSQueryUserToken with args: [1 18A80EA8]
2019/07/10 17:54:09 Result: 0 0 An attempt was made to reference a token that does not exist.
2019/07/10 17:54:09 Making system call WTSGetActiveConsoleSessionId with args: []
2019/07/10 17:54:09 Result: 1 18D1D908 The operation completed successfully.
2019/07/10 17:54:09 Making system call WTSQueryUserToken with args: [1 18A80EA8]
2019/07/10 17:54:09 Result: 0 0 An attempt was made to reference a token that does not exist.
2019/07/10 17:54:09 Making system call WTSGetActiveConsoleSessionId with args: []
2019/07/10 17:54:09 Result: 1 18D1D908 The operation completed successfully.
2019/07/10 17:54:09 Making system call WTSQueryUserToken with args: [1 18A80EA8]
2019/07/10 17:54:09 Result: 0 0 An attempt was made to reference a token that does not exist.
2019/07/10 17:54:09 Making system call WTSGetActiveConsoleSessionId with args: []
2019/07/10 17:54:09 Result: 1 18D1D908 The operation completed successfully.
2019/07/10 17:54:09 Making system call WTSQueryUserToken with args: [1 18A80EA8]
2019/07/10 17:54:09 Result: 0 0 An attempt was made to reference a token that does not exist.
2019/07/10 17:54:09 Making system call WTSGetActiveConsoleSessionId with args: []
2019/07/10 17:54:09 Result: 1 18D1D908 The operation completed successfully.
2019/07/10 17:54:09 Making system call WTSQueryUserToken with args: [1 18A80EA8]
2019/07/10 17:54:09 Result: 0 0 An attempt was made to reference a token that does not exist.
2019/07/10 17:54:10 Making system call WTSGetActiveConsoleSessionId with args: []
2019/07/10 17:54:10 Result: 1 18D1D908 The operation completed successfully.
2019/07/10 17:54:10 Making system call WTSQueryUserToken with args: [1 18A80EA8]
2019/07/10 17:54:10 Result: 0 0 An attempt was made to reference a token that does not exist.
2019/07/10 17:54:10 Making system call WTSGetActiveConsoleSessionId with args: []
2019/07/10 17:54:10 Result: 1 18D1D908 The operation completed successfully.
2019/07/10 17:54:10 Making system call WTSQueryUserToken with args: [1 18A80EA8]
2019/07/10 17:54:10 Result: 1 0 The operation completed successfully.
2019/07/10 17:54:10 Making system call GetUserProfileDirectoryW with args: [454 0 18BA17DC]
2019/07/10 17:54:10 Result: 0 2 The data area passed to a system call is too small.
2019/07/10 17:54:10 Making system call GetUserProfileDirectoryW with args: [454 18A31EF0 18BA17DC]
2019/07/10 17:54:10 Result: 1 2 The operation completed successfully.
2019/07/10 17:54:10 Making system call WTSGetActiveConsoleSessionId with args: []
2019/07/10 17:54:10 Result: 1 18D1D8F4 The operation completed successfully.
2019/07/10 17:54:10 Making system call WTSQueryUserToken with args: [1 18BA1830]
2019/07/10 17:54:10 Result: 1 0 The operation completed successfully.
2019/07/10 17:54:10 Making system call GetUserProfileDirectoryW with args: [458 0 18BA1854]
2019/07/10 17:54:10 Result: 0 2 The data area passed to a system call is too small.
2019/07/10 17:54:10 Making system call GetUserProfileDirectoryW with args: [458 18D14000 18BA1854]
2019/07/10 17:54:10 Result: 1 2 The operation completed successfully.
2019/07/10 17:54:10 Saving file file-caches.json (absolute path: C:\generic-worker\file-caches.json)
2019/07/10 17:54:10 Saving file directory-caches.json (absolute path: C:\generic-worker\directory-caches.json)
2019/07/10 17:54:10 goroutine 1 [running]:
runtime/debug.Stack(0x0, 0x0, 0x18ba8050)
/home/travis/.gimme/versions/go1.10.8.src/src/runtime/debug/stack.go:24 +0x8a
main.HandleCrash(0x869c60, 0x18ba9920)
/home/travis/gopath/src/github.com/taskcluster/generic-worker/main.go:344 +0x1e
main.RunWorker.func1(0x18e6ff1c)
/home/travis/gopath/src/github.com/taskcluster/generic-worker/main.go:363 +0x3d
panic(0x869c60, 0x18ba9920)
/home/travis/.gimme/versions/go1.10.8.src/src/runtime/panic.go:502 +0x1d0
main.PlatformTaskEnvironmentSetup(0x18a80df0, 0xf, 0x5)
/home/travis/gopath/src/github.com/taskcluster/generic-worker/multiuser.go:56 +0xa03
main.PrepareTaskEnvironment(0x2)
/home/travis/gopath/src/github.com/taskcluster/generic-worker/main.go:1104 +0xa9
main.RotateTaskEnvironment(0x18c3dc00)
/home/travis/gopath/src/github.com/taskcluster/generic-worker/main.go:1175 +0x1a
main.RunWorker(0x0)
/home/travis/gopath/src/github.com/taskcluster/generic-worker/main.go:419 +0x406
main.main()
/home/travis/gopath/src/github.com/taskcluster/generic-worker/main.go:151 +0x654
2019/07/10 17:54:10 *********** PANIC occurred! ***********
2019/07/10 17:54:10 Interactive username testdroid does not match task user task_1562746981 from next-task-user.json file
2019/07/10 17:54:10 No sentry project defined, not reporting to sentry
2019/07/10 17:54:10 Exiting worker with exit code 69
|
||
Comment 1•7 years ago
|
||
(In reply to Edwin Gao (:egao) from comment #0)
...
- remove
next-task-user.json
...
2019/07/10 17:54:10 Interactive username testdroid does not match task user task_1562746981 from next-task-user.json file
It looks like the next-task-user.json file might not have been deleted before the machine was restarted (based on the error message). This is probably located at C:\generic-worker\next-task-user.json. But in any case, a factory reset of the machines is a good idea, as the earlier versions of generic-worker were not managing task users correctly, so if there were hundreds of user accounts on the machine, probably not a bad idea to factory reset it.
Let me know how you get on after that, and also if multiple task user accounts persist on the machine. There should only be two task user accounts at any time.
|
Reporter | |
Comment 2•7 years ago
•
|
||
:pmoore - I was experimenting with my own hardware I have on hand, and I was able to reproduce the same exception that Bitbar was encountering.
The contents of both next-task-user.json and current-task-user.json were empty/null.
Registry keys noted did not exist on my local hardware.
With 15.1.0, user accounts were not deleted when generic-worker was run; instead it created a few more, and they persisted.
Now, when I dropped in the 15.0.1 i386 binary into the installed directory and hot-swapped with the 15.1.0 binary, the tasks appear to have started running at least:
Still getting 'access denied' for an odd reason (for cd no less) but unless you object, it may make sense to have Bitbar use 15.0.1 worker instead for the time being.
|
|
||
Comment 3•7 years ago
•
|
||
Hi Edwin,
I'm sorry you have been encountering these issues, it sounds like there is indeed a problem, which perhaps may be specific to ARM64 hardware.
We are running 15.1.0 in production for the other windows gecko worker types (below), also 386 workers which use the same release as the ARM64 workers, but strangely we are not encountering the same issue:
gecko-1-b-win2012: generic-worker 15.1.0
gecko-1-b-win2012-beta: generic-worker 15.1.0
gecko-2-b-win2012: generic-worker 15.1.0
gecko-3-b-win2012: generic-worker 15.1.0
gecko-t-win10-64: generic-worker 15.1.0
gecko-t-win10-64-beta: generic-worker 15.1.0
gecko-t-win10-64-cu: generic-worker 15.1.0
gecko-t-win10-64-gpu: generic-worker 15.1.0
gecko-t-win10-64-gpu-b: generic-worker 15.1.0
gecko-t-win7-32: generic-worker 15.1.0
gecko-t-win7-32-beta: generic-worker 15.1.0
gecko-t-win7-32-cu: generic-worker 15.1.0
gecko-t-win7-32-gpu: generic-worker 15.1.0
gecko-t-win7-32-gpu-b: generic-worker 15.1.0
I have access to an ARM64 windows laptop, I'll see if I can reproduce, and if I can, I'll hook the worker up to the generic-worker CI to help avoid issues like this in future. Apologies for the inconvenience.
Pete
|
|
||
Comment 4•7 years ago
|
||
(In reply to Edwin Gao (:egao) from comment #2)
Still getting 'access denied' for an odd reason (for
cdno less) but unless you object, it may make sense to have Bitbar use 15.0.1 worker instead for the time being.
If it works ok, that is fine with me. 14.1.2 is another option, if you have issues with 15.0.1. But as I am not sure what is causing the current issue, I don't really know which releases are affected by it yet, so I can't promise that you won't hit the same issue. :-/
|
|
||
Comment 5•7 years ago
|
||
(In reply to Edwin Gao (:egao) from comment #0)
2019/07/10 17:54:10 Interactive username testdroid does not match task user task_1562746981 from next-task-user.json file
Looking at this again, I am very confident that the file C:\generic-worker\next-task-user.json file had not been deleted, since the generic-worker was started at 2019/07/10 17:50:37 UTC but the task user name includes a unix timestamp (1562746981) from the time the user was created. That maps to 2019/07/10 08:23:01 UTC, i.e. 9.5 hours earlier.
Also looking at the code, we can see that the execution path that returns that error message is only executed if the next-task-user.json file was already present.
Checking all the call sites for that function, we see it is called precisely once on start up, and then between each executed task, and that the file is first written further down in the same function so it isn't possible that the file is created on the same run that it exits with this error, the generic-worker must have been started at least twice. However, due to the 9.5 hour time gap, my guess is that is also not the case for this log.
If you still believe this is an issue, can you please send me the complete log from your laptop too. Also please let me know if you have news from the bitbar people, whether the machine reimaging solved the issue for them.
I'm also keen to understand why user accounts are not getting deleted, if you have logs from workers that are not deleting user accounts, I would be happy to take a look.
We can also meet up and have a screen-share if that helps, or if you have RDP details for a worker, I'm happy to hop on one and have a look.
Many thanks!
|
|
Reporter | |
Comment 6•7 years ago
•
|
||
|
|
Reporter | |
Comment 7•7 years ago
|
||
Not sure why markdown isn't being applied to the above post.
|
|
||
Comment 8•7 years ago
•
|
||
It seems like the auto-login must be broken.
The worker creates a task user, sets the Windows registry to auto-login as that user, and then reboots the machine.
The worker is running as a Windows Service, and waits for the interactive desktop login to complete, and then checks that the user that is logged in, is the actual user it created for the task to run as. If it is a different user (e.g. egao or testdroid) it will intentionally exit, since it doesn't want to run tasks as those (privileged) users.
If the worker installs ok, and on first run successfully reboots the computer, that indicates things are working correctly to start with. If when it reboots for the first time, the auto-login doesn't complete (and you need to manually log in), it indicates something is broken with the auto-login process.
If it does log in as the task user automatically, and then the worker panics, it is a different problem. Until now all the logs I have seen suggest that a task user is not logged in at the time the worker panics, but a real user is logged in (egao / testdroid).
Are the log files from the laptops being sent to papertrail? Can we view the full log history of one of the workers after it was freshly installed?
Alternatively, can I have RDP access to a worker?
If not, is it possible to get the full logs from a worker at the point it panics, while the task user is still logged in (rather than logging in as an actual user to retrieve the logs, and then having the worker fail due to a non-task user being logged in).
Thanks!
|
||
Comment 9•7 years ago
|
||
Unfortunately I don't think we can RDP to any of the Windows hardware at Bitbar. Which I think we need to address in the long term. While working with them it has been through Slack requesting a command run and getting screenshots back.
I will spin up a Moonshot tester pool using gw 15.1.0 next week and load up with tasks, so that we can see if this is unique to the architecture or static/hardware nodes.
|
|
||
Comment 10•7 years ago
|
||
(In reply to Mark Cornmesser [:markco] from comment #9)
Unfortunately I don't think we can RDP to any of the Windows hardware at Bitbar. Which I think we need to address in the long term. While working with them it has been through Slack requesting a command run and getting screenshots back.
I will spin up a Moonshot tester pool using gw 15.1.0 next week and load up with tasks, so that we can see if this is unique to the architecture or static/hardware nodes.
See comment 3 - we're already running 15.1.0 in production on most of our worker types.
|
|
||
Comment 11•7 years ago
•
|
||
See comment 3 - we're already running 15.1.0 in production on most of our worker types.
The statement should had been more explicit to Windows static/hardware nodes.
|
|
||
Comment 12•6 years ago
•
|
||
So, if a non task user logs into the interactive desktop session (e.g. testdroid / egao) I would expect exactly the behaviour described: the worker should panic, and report that the current interactive user is not the task user it was expecting, since it relies on the task user being logged in, in order to run the next task as the task user inside the interactive desktop session.
Once a user has manually logged in, and the worker has panicked, the winlogon registry would need to be reset, and the next-task-user.json and current-task-user.json files deleted in order for the worker to recover after a reboot. Just rebooting the worker isn't enough. The state has been soiled once a user manually logs in.
I'm suspicious if the problem is that in order to check whether the worker is operating correctly, an operator is logging into the interactive desktop session to check the logs, causing the panic, and then seeing the panic and thus reasoning that the worker wasn't working. I think the best way to overcome this, if this is what was happening, is for the workers to log to e.g. papertrail, and the logs to be tailed remotely, rather than an operator logging into the interactive desktop session of the laptop in question. As soon as the operator logs in, the worker will no longer work, unless the state is cleaned (winlogon auto-login registry settings reset, task user json files deleted).
|
|
||
Updated•6 years ago
|
|
|
||
Updated•6 years ago
|
|
|
Reporter | |
Comment 14•6 years ago
|
||
It's been so long since I was involved with windows10-aarch64, but AFAIK this is no longer an issue. Thanks for checking!
|
|
||
Comment 15•6 years ago
|
||
Great, thanks! :-)
Description
•