Python commands are printed twice in the output channel

Environment data

VS Code version: 1.37.1
Extension version (available under the Extensions sidebar): master 39cf9e0
OS and version: macOS Mojave 10.14.6

Expected behaviour

Python commands should only be displayed once in the "Python" output channel.

Actual behaviour

Some Python commands (for example linting or formatting) are displayed twice.

Steps to reproduce:

Start debugging the extension
Open a python file and enable linting or formatting on save
Set 2 breakpoints:
- vscode-python/src/client/common/process/logger.ts
  
  Line 19 in 39cf9e0
  
  const argsList = args.reduce((accumulator, current, index) => {
- vscode-python/src/client/common/process/proc.ts
  
  Line 184 in 39cf9e0
  
  this.emit('exec', file, args, options);
Save the file
Notice that this.emit('exec', file, args, options); is only hit once, but the debugger stops twice onlogger.logProcess().

Cause

We register 2 'exec' listeners to the python process:

In the create or createActivatedEnvironment method in PythonExecutionFactory:

vscode-python/src/client/common/process/pythonExecutionFactory.ts

Lines 31 to 37 in 39cf9e0

    
           public async create(options: ExecutionFactoryCreationOptions): Promise<IPythonExecutionService> { 
        
               const pythonPath = options.pythonPath ? options.pythonPath : this.configService.getSettings(options.resource).pythonPath; 
        
               const processService: IProcessService = await this.processServiceFactory.create(options.resource); 
        
               const processLogger = this.serviceContainer.get<IProcessLogger>(IProcessLogger); 
        
               processService.on('exec', processLogger.logProcess.bind(processLogger)); 
        
               return new PythonExecutionService(this.serviceContainer, processService, pythonPath); 
        
           }

But also in the call to await this.processServiceFactory.create:

vscode-python/src/client/common/process/processFactory.ts

Lines 21 to 26 in 39cf9e0

    
           public async create(resource?: Uri): Promise<IProcessService> { 
        
               const customEnvVars = await this.envVarsService.getEnvironmentVariables(resource); 
        
               const proc: IProcessService = new ProcessService(this.decoder, customEnvVars); 
        
               this.disposableRegistry.push(proc); 
        
               return proc.on('exec', this.processLogger.logProcess.bind(this.processLogger)); 
        
           }

As an easy-to-reproduce example of this, when I use "Format Document", the Python output log appears to show that Black is run twice:

~/.../.venv/bin/python -m black --diff --quiet ~/.../src/app/views.py.c64f5302f131d47a9d9da0861e28ac43.tmp
cwd: ~/...
~/.../.venv/bin/python -m black --diff --quiet ~/.../src/app/views.py.c64f5302f131d47a9d9da0861e28ac43.tmp
cwd: ~/...

Is there anything we can provide to get this issue some traction? I am mainly interested in whether commands are actually ran twice (which it seems it does). I'll gladly perform any tests or work with somebody to get this issue fixed!

Daniël van Noord (@DanielNoord)

Hi Daniël van Noord (@DanielNoord), if this issue gets more upvotes it'll help us prioritize it.

I am mainly interested in whether commands are actually ran twice (which it seems it does)

They are not, it is just the logger being called twice.

Verification steps:

Install latest extension using Python: Switch to Insiders command.
Open a workspace containing a python file, and open the file to activate the extension.
Create a new virtual environment: python -m venv .venv and select it as a interpreter using Python: Select Interpreter command.
Run Format document on a python file.
Follow prompt to install the formatter and attempt formatting again.
Ensure something similar to the following command:

"~\OneDrive - Microsoft\Desktop\folders\newone\.venv\Scripts\python.exe" -m autopep8 --diff "~\OneDrive - Microsoft\Desktop\folders\newone\s.py"
cwd: ~\OneDrive - Microsoft\Desktop\folders\newone

only appears once in the output panel.

Kartik Raj (@karrtikr)

Kartik Raj (@karrtikr) Does this mean this was not fixed? Or is this just a reproduction for future reference?

This was fixed by me, but it has to be verified by someone else (in the team or by the users) before we consider it as done, which is why I left the steps. You're welcome to test it as well.

Kartik Raj (@karrtikr)

Kartik Raj (@karrtikr), Not sure if this is working or not?

I get this:

Looks like it logs twice?

Can you turn off verbose logging and see if it logs twice? Verbose can log anything.

Yep that was it. Only logs once without verbose.

Navigation Menu

Repository navigation

Python commands are printed twice in the output channel #7160

Environment data

Expected behaviour

Actual behaviour

Steps to reproduce:

Cause

Verification steps:

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

	public async create(options: ExecutionFactoryCreationOptions): Promise<IPythonExecutionService> {
	const pythonPath = options.pythonPath ? options.pythonPath : this.configService.getSettings(options.resource).pythonPath;
	const processService: IProcessService = await this.processServiceFactory.create(options.resource);
	const processLogger = this.serviceContainer.get<IProcessLogger>(IProcessLogger);
	processService.on('exec', processLogger.logProcess.bind(processLogger));
	return new PythonExecutionService(this.serviceContainer, processService, pythonPath);
	}

	public async create(resource?: Uri): Promise<IProcessService> {
	const customEnvVars = await this.envVarsService.getEnvironmentVariables(resource);
	const proc: IProcessService = new ProcessService(this.decoder, customEnvVars);
	this.disposableRegistry.push(proc);
	return proc.on('exec', this.processLogger.logProcess.bind(this.processLogger));
	}

Python commands are printed twice in the output channel #7160

Description

Environment data

Expected behaviour

Actual behaviour

Steps to reproduce:

Cause

Activity

kbd commented on Jul 20, 2021

DanielNoord commented on Aug 5, 2021

kimadeline commented on Aug 9, 2021

karrtikr commented on Oct 25, 2021

Verification steps:

DanielNoord commented on Oct 25, 2021

karrtikr commented on Oct 25, 2021

rchiodo commented on Oct 27, 2021

karrtikr commented on Oct 27, 2021

rchiodo commented on Oct 27, 2021

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions