'The preLaunchTask 'xxxx' cannot be tracked.' exception after installing the October 1.18 release

[guardrex]

• VSCode Version: 1.18.0
• OS Version: Win10

Steps to Reproduce:

1. Use a task to run a dotnet command to build the project as a preLaunchTask in launch.json.
2. Debug the project.

Reproduces without extensions: Yes

In launch.json ...

{
    "name": ".NET Core Launch (web)",
    "type": "coreclr",
    "request": "launch",
    "preLaunchTask": "build",
    "program": "${workspaceRoot}/bin/Debug/netcoreapp2.0/ChangeTokenSample.dll",
    "args": [],
    "cwd": "${workspaceRoot}",
    ...

build task [I'm using an older format (e.g., taskName over label) due to some requirements here. tasks.json version: 0.1.0] ...

{
    "taskName": "build",
    "suppressTaskName": true,
    "args" : ["dotnet", "build", "--configuration", "Debug"],
    "showOutput": "always",
    "isBuildCommand": true,
    "problemMatcher": "$msCompile"
},

Starting with the 1.18.0 release, when I run the debugger, it throws this exception ...

The preLaunchTask 'build' cannot be tracked.

If that's normal now (i.e., not a bug), is there any way to disable it from throwing? The debugger still works fine, and the build task works fine all by itself, but I must click past this exception with the Debug Anyway button in order to get the debug session running. I'm not concerned whether or not the pre-launch task can be tracked or not (at least I'm not concerned yet 😄 lol).

[jessegavin]

I am having this issue as well. Started happening after the upgrade.

[guardrex]

I'm in the process now of testing with a 2.0.0 version of tasks.json. Maybe my use of an ancient version is hurting me. lol

[guardrex]

Yes ... that seems to have done the trick. I've upgraded my old tasks.json to 2.0 ...

{
    "type": "shell",
    "taskName": "build",
    "label": "build",
    "command" : "dotnet build --configuration Debug",
    "group": {
        "kind": "build",
        "isDefault": true
    },
    "problemMatcher": "$msCompile"
},

... and that silenced the exception.

Although it's obsolete, I must leave the old taskName in there for now. I have an old extension that still uses it.

I'll leave this open for a sec so that the team has a chance to say why this came up tho for version 0.1.0 of the tasks.json file.

[weinand]

@dbaeumer please advise

[jdneo]

I have the same problems after upgrade to 1.18.

My tasks.json:

{
  "version": "2.0.0",
  "tasks": [
    {
      "label": "Launch Function App",
      "identifier": "launchFunctionApp",
      "type": "shell",
      "command": "func host start --script-root target/azure-functions/test-1510276830503/",
      "isBackground": true,
      "presentation": {
        "reveal": "always"
      },
      "problemMatcher": [
        {
          "owner": "azureFunctions",
          "pattern": [
            {
              "regexp": "\\b\\B",
              "file": 1,
              "location": 2,
              "message": 3
            }
          ],
          "background": {
            "activeOnStart": true,
            "beginsPattern": "^.*Stopping host.*",
            "endsPattern": "^.*Job host started.*"
          }
        }
      ],
      "dependsOn": "mavenCleanPackage"
    },
    {
      "label": "Maven Clean Package",
      "identifier": "mavenCleanPackage",
      "type": "shell",
      "command": "mvn",
      "args": [
        "clean",
        "package"
      ],
      "isBackground": true
    }
  ]
}

-----------Update---------------
Seems this is because I have to first execute the depeneded task: mvn clean package, and it will take a long time which is longer than 10s, and vscode will throw error if it cannot detect the task has been started in 10s.

https://github.com/Microsoft/vscode/blob/9095c3951063e5a32b52fcf877340abdc0abd2d4/src/vs/workbench/parts/debug/electron-browser/debugService.ts#L974-L978

[dbaeumer]

I tried to reproduce this with a simple dotnet console application and was not able to using the following files
tasks.json

{
	"version": "0.1.0",
	"tasks": [
		{
			"taskName": "build",
			"suppressTaskName": true,
			"command": "dotnet",
			"args": [
				"build",
				"--configuration",
				"Debug"
			],
			"showOutput": "always",
			"isBuildCommand": true,
			"problemMatcher": "$msCompile"
		}
	]
}

launch.json

{
   // Use IntelliSense to find out which attributes exist for C# debugging
   // Use hover for the description of the existing attributes
   // For further information visit https://github.com/OmniSharp/omnisharp-vscode/blob/master/debugger-launchjson.md
   "version": "0.2.0",
   "configurations": [
        {
            "name": ".NET Core Launch (console)",
            "type": "coreclr",
            "request": "launch",
            "preLaunchTask": "build",
            // If you have changed target frameworks, make sure to update the program path.
            "program": "${workspaceFolder}/bin/Debug/netcoreapp2.0/37997.dll",
            "args": [],
            "cwd": "${workspaceFolder}",
            // For more information about the 'console' field, see https://github.com/OmniSharp/omnisharp-vscode/blob/master/debugger-launchjson.md#console-terminal-window
            "console": "internalConsole",
            "stopAtEntry": false,
            "internalConsoleOptions": "openOnSessionStart"
        },
        {
            "name": ".NET Core Attach",
            "type": "coreclr",
            "request": "attach",
            "processId": "${command:pickProcess}"
        }
    ]
}

I generated the example using dotnet new console.

[dbaeumer]

So tasks 0.1.0 seems to send the right events.

@guardrex can you provide a more complete example so that we can investigate. Could it be that the tasks.json specifies isWatching / isBackground also the dotnet command is not actually running in background?

@jdneo example I think is different. It uses 2.0.0 and I guess that debugging never receives an activate event. But without a complete example it is hard to say why this is happening.

@isidorn may be we should introduce a special event to make this less dependent on a correct configuration.

[guardrex]

@dbaeumer Sure thing. I'm slammed this afternoon, but I'll get that for you by the end of the day.

[guardrex]

@dbaeumer Yes, it still repros with the Change Tokens sample I was working on. If I click to Debug Anyway, it seems to run fine. My fix is simply to take my task.json files to 2.0.0, so I'm not blocked.

https://github.com/guardrex/ChangeTokenSample

[robbpriestley]

+1 having this issue. This is my tasks.json:

{
    "version": "0.1.0",
    "command": "dotnet",
    "isShellCommand": true,
    "args": [],
    "tasks": [
    	{
            "taskName": "build",
	    	"command": "${workspaceRoot}/build.sh",
	    	"isShellCommand": true,
	    	"isBuildCommand": true
        },
    	{
    		"taskName": "transpile",
    		"command": "tsc",
    		"args": ["-p", "./wwwroot/js/tsconfig.json", "--outDir", "./wwwroot/js/"],
    		"isShellCommand": true,
    		"isTestCommand": true
    	}
    ]
}

[jdneo]

Hi @dbaeumer, thanks for replying. Here is my launch.json:

{
  "version": "0.2.0",
  "configurations": [
    {
      "name": "Attach to Azure Functions",
      "type": "java",
      "request": "attach",
      "hostName": "localhost",
      "port": 5005,
      "preLaunchTask": "launchFunctionApp"
    }
  ]
}

and task.json:

{
  "version": "2.0.0",
  "tasks": [
    {
      "label": "Launch Function App",
      "identifier": "launchFunctionApp",
      "type": "shell",
      "command": "func host start --script-root target/azure-functions/test-1510276830503/",
      "isBackground": true,
      "presentation": {
        "reveal": "always"
      },
      "problemMatcher": [
        {
          "owner": "azureFunctions",
          "pattern": [
            {
              "regexp": "\\b\\B",
              "file": 1,
              "location": 2,
              "message": 3
            }
          ],
          "background": {
            "activeOnStart": true,
            "beginsPattern": "^.*Stopping host.*",
            "endsPattern": "^.*Job host started.*"
          }
        }
      ],
      "dependsOn": "mavenCleanPackage"
    },
    {
      "label": "Maven Clean Package",
      "identifier": "mavenCleanPackage",
      "type": "shell",
      "command": "mvn",
      "args": [
        "clean",
        "package"
      ],
      "isBackground": true
    }
  ]
}

As you can see, in my launch.json, I have a preLaunchTask, and this task depend on another task mvn clean package which will take more than 10s. So each time after 10s, the error will show on the top. Though I can click debug anyway to do the debug and it works.

I find this commit may be the relative commit in 1.18

[dbaeumer]

@guardrex interestingly I was not able to reproduce this using the change token sample. When you see that happen does it take a long time until the task starts. Debug waits 10 seconds for the start to happen and if it doesn't signals this to the user.

[dbaeumer]

OK. I debugged this a little and the reason is that node emitters are deferring events. Also I call the emit quite early it takes even on my machine a little to fire the event. Especially when the started task takes a while to spawn the child process since this is async.

To make sure we are not hit by this event firing needs to happen sync which I actually hate to do.

@isidorn, @weinand may be we need to think about a different strategy about detecting a not completed start.

[weinand]

@dbaeumer are you saying that the start event is delayed and debug's timeout of 10 seconds is not sufficient?

[dbaeumer]

Yes, it looks like this. I debugged through the example I got from @guardrex and all events are fired correctly, but the node event emitter delays them in a deferred queue. Right after that we do some child process spawning.

I would assume that 10 seconds should be enough. So may be you could look at the debug code as well to see if there is something that could cause some problems.

[edvinv]

In my situation I'm running webpack and it takes around 16 seconds to compile. After 10 seconds I get "The preLaunchTask 'xxx' cannot be tracked."

Also, in task terminal I see all output from webpack generated at the end, none at first 10 seconds.

[guardrex]

When you see that happen does it take a long time until the task starts.

Yes, I repeated the debugging startup several times and timed it, and the message pops up right at ~10 seconds every time.

[weswigham]

If you still need a repro, I can reproduce this over at TypeScript with a launch.json of

{
    // Use IntelliSense to learn about possible Node.js debug attributes.
    // Hover to view descriptions of existing attributes.
    // For more information, visit: https://go.microsoft.com/fwlink/?linkid=830387
    "version": "0.2.0",
    "configurations": [
        {
            "type": "node",
            "request": "launch",
            "name": "Mocha Tests (currently opened test)",
            "program": "${workspaceRoot}/node_modules/mocha/bin/_mocha",
            "args": [
                "-u",
                "tdd",
                "--timeout",
                "2000000",
                "--colors",
                "built/local/run.js",
                "-f",
                "${fileBasenameNoExtension}"
            ],
            "env": {
                "NODE_ENV": "testing"
            },
            "stopOnEntry": false,
            "sourceMaps": true,
            "console": "integratedTerminal",
            "preLaunchTask": "tests"
        },
        {
            "type": "node",
            "request": "attach",
            "name": "Attach to Process",
            "processId": "${command:PickProcess}",
            "port": 9229
        },
        {
            "type": "node",
            "request": "launch",
            "name": "Launch Program",
            "program": "${workspaceRoot}\\lib\\typescript.js",
            "outFiles": [
                "${workspaceRoot}/out/**/*.js"
            ]
        }
    ]
}

while attempting to run the Mocha Tests (currently opened test) task with no built target yet (so the preLaunchTask takes time to run).
The tasks.json reads:

// Available variables which can be used inside of strings.
// ${workspaceRoot}: the root folder of the team
// ${file}: the current opened file
// ${fileBasename}: the current opened file's basename
// ${fileDirname}: the current opened file's dirname
// ${fileExtname}: the current opened file's extension
// ${cwd}: the current working directory of the spawned process
{
    "version": "0.1.0",
    "command": "gulp",
    "isShellCommand": true,
    "showOutput": "silent",
    "tasks": [
        {
            "taskName": "local",
            "isBuildCommand": true,
            "showOutput": "silent",
            "problemMatcher": [
                "$tsc"
            ]
        },
        {
            "taskName": "tests",
            "showOutput": "silent",
            "problemMatcher": [
                "$tsc"
            ]
        }
    ]
}

Worked fine prior to this release.

[dbaeumer]

Just to clarify some things: we wait 10 seconds for the task to report it started not for the task to finish. This basically means this event, which we sent out before we actually start the task using either a terminal in task v2 or a child process in v0.1.0 is not being delivered to the debug service in 10 seconds. The only difference are background tasks. For those we fire the event when finding the begin pattern in the output. But neither the example from @guardrex nor from @weswigham uses background tasks.

[guardrex]

@dbaeumer Thanks Dirk for continuing the investigation. My situation has cleared up thus far by upgrading my files to v2.0.0, but it looks like some cats are running into this even with v2.0.0 files. I will say as a funny side note that I'm on ...

i7-3770K @ 3.50 GHz

Time for an upgrade to an i9?? lol 😄 ... I was looking for an excuse to build a new PC. Let me know. If anyone asks me why the hell I spent $1,000 on a CPU, I can say that "Dirk told me that I had to do it!" lol 😀

[iSazonov]

The same is in PowerShell repo. I tried to switch to v2 and it works.

[dbaeumer]

Continued debugging this showed that the events are NOT deferred. This was a source map problem :-(.
After debugging this in plain JS all events where sent synch.

However looking at the debug code I noticed the following problems:

• the task is not marked as taskStarted if the start fails (the error case)
• WinJS promises that are resolved executed sync on then callbacks.

For the debug code that mean that the code here:

			const promise = this.taskService.getActiveTasks().then(tasks => {
				if (tasks.filter(t => t._id === task._id).length) {
					// task is already running - nothing to do.
					return TPromise.as(null);
				}

				const taskPromise = this.taskService.run(task);
				if (task.isBackground) {
					return new TPromise((c, e) => this.toDispose.push(this.taskService.addOneTimeListener(TaskServiceEvents.Inactive, () => c(null))));
				}

				return taskPromise;
			});

executes full sync when the task system is fully resolved (I cache promises heavily and reuse their result if not invalidated)

If this happens the TaskServiceEvents.Active listener is hooked to late and might miss the event. If the task then needs more than 10 seconds to complete the message is shown.

@isidorn can you please have a look.

Besides the above I think the code might have the potential to leak listeners as well. If you miss the event then the listener only gets disposed if the debug service gets disposed. So IMO the code should keep the disposable locally and dispose it when the tasks either finished or errors.

[dbaeumer]

@isidorn See the attached screen shot which shows the sequence in the debugger:

[weinand]

Since this issue affects users of the "preLaunchTask" attribute across all debuggers, I think a fix should go into the recovery release.

[isidorn]

@dbaeumer thanks for this great investigation.
Following your advice I have pushed 304e001 Basically now I am listening to the task events before going to the taskService.run
@dbaeumer Can you please code review?

I have checked and everything seems to work fine on my machine. Though please note that I was never able to reproduce the issue described in the first comment.
As for the listeners leak this is fixed via 2432b74 however that I will not chery pick on release since this is not critical, thus the seperate commit.

[dbaeumer]

@isidorn the change looks good to me. However I think in the error case what could happen is the following:

• the run fails early before the event is sent
• the timer is still installed
• taskStarted is not set to true
• the user sees an error that the task failed
• 10 seconds later he gets an error saying that the task can't be tracked.

May be not critical for a recovery build

[isidorn]

@dbaeumer thanks for the review.
However I think your observation can not happen, because if the task failed before the event is sent then the promise will already complete with the error case here
The timeout will after 10s try to copmlete the promise with the error case, but that already happened and this will not have any effect.

Even if I am wrong I think this is not critical for the recovery build, thus I am cherry picking my commit on top of the release branch.
Thanks!

[dbaeumer]

@isidorn your analysis is correct. The second resolve of the error promise will be a noop.

[isidorn]

It would be great if someone from the users seeing the problem could verify the fix solves the issue for them. Here are the links to vscode builds which contain the fix

win64
win32
mac

If somebody is on linux let me know what version of code you need and I will provide a link

[iSazonov]

It (win32) works for me - many thanks!

[isidorn]

@iSazonov great, thanks for verifying. This will be in stable in the next couple of days

[Sequoia]

1. Is there any workaround for this for the time being?
2. Is a fix "a long way off" or "coming in the next few days/weeks"?

Thanks!

[isidorn]

1. use vscode insiders
2. next few days