Language server hangs on analysis stage

[zztalker]

Environment data

• Language Server version: Microsoft Python Language Server version 0.4.127.0
• OS and version: Linuxmint 19.2 (Ubuntu 18)
• Python version (& distribution if applicable, e.g. Anaconda): python3.5

Expected behaviour

Works

Actual behaviour

Doesn't work

Logs

[Info  - 10:44:22 AM] Analysis cache path: /home/pz/.cache/Microsoft/Python Language Server
[Info  - 10:44:22 AM] Microsoft Python Language Server version 0.4.127.0
[Info  - 10:44:22 AM] Workspace root: /home/pz/defence360/src/rpm-tests
[Info  - 10:44:22 AM] GetCurrentSearchPaths /opt/alt/python35/bin/python3 
[Info  - 10:44:22 AM] Interpreter search paths:
[Info  - 10:44:22 AM]     /opt/alt/python35/lib/python3.5
[Info  - 10:44:22 AM]     /opt/alt/python35/lib/python3.5/plat-linux
[Info  - 10:44:22 AM]     /opt/alt/python35/lib/python3.5/lib-dynload
[Info  - 10:44:22 AM]     /home/pz/defence360/src/asyncclient
[Info  - 10:44:22 AM]     /home/pz/.local/lib/python3.5/site-packages
[Info  - 10:44:22 AM]     /opt/alt/python35/local/lib/python3.5/dist-packages
[Info  - 10:44:22 AM]     /opt/alt/python35/lib/python3/dist-packages
[Info  - 10:44:22 AM]     /opt/alt/python35/lib/python3.5/dist-packages
[Info  - 10:44:22 AM] User search paths:
[Info  - 10:44:23 AM] Initializing for /opt/alt/python35/bin/python3
Watching /opt/alt/python35/lib/python3.5
Watching /home/pz/defence360/src/asyncclient
Watching /home/pz/.local/lib/python3.5/site-packages
Watching /opt/alt/python35/lib/python3/dist-packages
Watching /opt/alt/python35/local/lib/python3.5/dist-packages
[Info  - 10:44:24 AM] Analysis caching mode: None.
Opening document file:///home/pz/defence360/src/rpm-tests/fixtures/hosting_panel/plesk.py
Analysis of fixtures.hosting_panel.plesk (User) queued. Dependencies: os, subprocess, distutils.version, pathlib, xml.etree, xml.etree.ElementTree, fixtures.hosting_panel, fixtures.hosting_panel.abstract, utils
Import:  os /opt/alt/python35/lib/python3.5/os.py 
Import:  subprocess /opt/alt/python35/lib/python3.5/subprocess.py 
Import:  distutils.version /opt/alt/python35/lib/python3.5/distutils/version.py 
Import:  pathlib /opt/alt/python35/lib/python3.5/pathlib.py 
Import:  xml.etree /opt/alt/python35/lib/python3.5/xml/etree/__init__.py 
Import:  xml.etree.ElementTree /opt/alt/python35/lib/python3.5/xml/etree/ElementTree.py 
Import:  fixtures.hosting_panel /home/pz/defence360/src/rpm-tests/fixtures/hosting_panel/__init__.py 
[skipped a lot of lines]
Analysis of modules loop on depth 0 in 293.89 ms:
    utils(User)
    utils.webshield(User)
Create compiled (scraped):  _datetime /opt/alt/python35/lib/python3.5/lib-dynload/_datetime.cpython-35m-x86_64-linux-gnu.so /opt/alt/python35/lib/python3.5/lib-dynload 
Import:  optparse /opt/alt/python35/lib/python3.5/optparse.py 
Import:  ast /opt/alt/python35/lib/python3.5/ast.py 
Analysis of modules loop [inspect(Library), ast(Library)] failed. System.ArgumentNullException: Value cannot be null. (Parameter 'ast')
   at Microsoft.Python.Analysis.Analyzer.Evaluation.ExpressionEval..ctor(IServiceContainer services, IPythonModule module, PythonAst ast) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\Evaluation\ExpressionEval.cs:line 43
   at Microsoft.Python.Analysis.Analyzer.Handlers.LoopImportedVariableHandler.WalkModule(IPythonModule module, PythonAst ast) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\Handlers\LoopImportedVariableHandler.cs:line 119
   at Microsoft.Python.Analysis.Analyzer.Handlers.LoopImportedVariableHandler.WalkModule(IPythonModule module, PythonAst ast) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\Handlers\LoopImportedVariableHandler.cs:line 118
   at Microsoft.Python.Analysis.Analyzer.Handlers.LoopImportedVariableHandler.EnsureModule(IPythonModule& module) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\Handlers\LoopImportedVariableHandler.cs:line 104
   at Microsoft.Python.Analysis.Analyzer.Handlers.LoopImportedVariableHandler.EnsureModule(PythonVariableModule& variableModule) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\Handlers\LoopImportedVariableHandler.cs:line 94
   at Microsoft.Python.Analysis.Analyzer.Handlers.LoopImportedVariableHandler.Microsoft.Python.Analysis.Analyzer.Handlers.IImportedVariableHandler.EnsureModule(PythonVariableModule& module)
   at Microsoft.Python.Analysis.Analyzer.Handlers.ImportHandler.HandleImport(ModuleName moduleImportExpression, NameExpression asNameExpression, Boolean forceAbsolute) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\Handlers\ImportHandler.cs:line 63
   at Microsoft.Python.Analysis.Analyzer.Handlers.ImportHandler.HandleImport(ImportStatement node) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\Handlers\ImportHandler.cs:line 46
   at Microsoft.Python.Analysis.Analyzer.AnalysisWalker.Walk(ImportStatement node) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\AnalysisWalker.cs:line 85
   at Microsoft.Python.Parsing.Ast.ImportStatement.Walk(PythonWalker walker) in E:\A\_work\2\s\src\Parsing\Impl\Ast\ImportStatement.cs:line 48
   at Microsoft.Python.Parsing.Ast.SuiteStatement.Walk(PythonWalker walker) in E:\A\_work\2\s\src\Parsing\Impl\Ast\SuiteStatement.cs:line 40
   at Microsoft.Python.Parsing.Ast.PythonAst.Walk(PythonWalker walker) in E:\A\_work\2\s\src\Parsing\Impl\Ast\PythonAst.cs:line 86
   at Microsoft.Python.Analysis.Analyzer.Handlers.LoopImportedVariableHandler.WalkModule(IPythonModule module, PythonAst ast) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\Handlers\LoopImportedVariableHandler.cs:line 123
   at Microsoft.Python.Analysis.Analyzer.PythonAnalyzerSession.AnalyzeLoop(IDependencyChainLoopNode`1 loopNode, Stopwatch stopWatch) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\PythonAnalyzerSession.cs:line 409
   at Microsoft.Python.Analysis.Analyzer.PythonAnalyzerSession.Analyze(IDependencyChainNode node, AsyncCountdownEvent ace, Stopwatch stopWatch) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\PythonAnalyzerSession.cs:line 284
Import:  faker.generator /opt/alt/python35/local/lib/python3.5/dist-packages/faker/generator.py 
Import:  faker.factory /opt/alt/python35/local/lib/python3.5/dist-packages/faker/factory.py 
Import:  faker /opt/alt/python35/local/lib/python3.5/dist-packages/faker/__init__.py 
Import:  faker.config /opt/alt/python35/local/lib/python3.5/dist-packages/faker/config.py 
Analysis of modules loop on depth 1 in 18.27 ms:
    faker.factory(Library)
    faker(Library)
Analysis version 285 has been completed in 3910.72 ms with 135 entries analyzed and 59 entries skipped.
Analysis version 1361 of 52 entries has started.
[skipped a lot of lines]
Analysis of sys(Stub) canceled (no AST yet).
Analysis version 1386 has been completed in 0.44 ms with 19 entries analyzed and 32 entries skipped.
Analysis of cryptography.x509.general_name (Library) on depth 4 completed in 5.76 ms.
Import:  cryptography.hazmat.backends.openssl.decode_asn1 /opt/alt/python35/lib/python3/dist-packages/cryptography/hazmat/backends/openssl/decode_asn1.py 
Import:  cryptography.hazmat.primitives.serialization /opt/alt/python35/lib/python3/dist-packages/cryptography/hazmat/primitives/serialization.py 
Analysis of cryptography.hazmat.backends.openssl.x509 (Library) on depth 3 completed in 8.42 ms.
Analysis of urllib3.packages (Library) on depth 3 completed in 0.25 ms.
Analysis of modules loop [urllib.request(Library), http.cookiejar(Library)] failed. System.ArgumentNullException: Value cannot be null. (Parameter 'ast')
   at Microsoft.Python.Analysis.Analyzer.Evaluation.ExpressionEval..ctor(IServiceContainer services, IPythonModule module, PythonAst ast) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\Evaluation\ExpressionEval.cs:line 43
   at Microsoft.Python.Analysis.Analyzer.Handlers.LoopImportedVariableHandler.WalkModule(IPythonModule module, PythonAst ast) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\Handlers\LoopImportedVariableHandler.cs:line 119
   at Microsoft.Python.Analysis.Analyzer.Handlers.LoopImportedVariableHandler.WalkModule(IPythonModule module, PythonAst ast) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\Handlers\LoopImportedVariableHandler.cs:line 118
   at Microsoft.Python.Analysis.Analyzer.Handlers.LoopImportedVariableHandler.EnsureModule(IPythonModule& module) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\Handlers\LoopImportedVariableHandler.cs:line 104
   at Microsoft.Python.Analysis.Analyzer.Handlers.LoopImportedVariableHandler.EnsureModule(PythonVariableModule& variableModule) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\Handlers\LoopImportedVariableHandler.cs:line 94
   at Microsoft.Python.Analysis.Analyzer.Handlers.LoopImportedVariableHandler.Microsoft.Python.Analysis.Analyzer.Handlers.IImportedVariableHandler.EnsureModule(PythonVariableModule& module)
   at Microsoft.Python.Analysis.Analyzer.Handlers.ImportHandler.HandleImport(ModuleName moduleImportExpression, NameExpression asNameExpression, Boolean forceAbsolute) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\Handlers\ImportHandler.cs:line 63
   at Microsoft.Python.Analysis.Analyzer.Handlers.ImportHandler.HandleImport(ImportStatement node) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\Handlers\ImportHandler.cs:line 46
   at Microsoft.Python.Analysis.Analyzer.AnalysisWalker.Walk(ImportStatement node) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\AnalysisWalker.cs:line 85
   at Microsoft.Python.Parsing.Ast.ImportStatement.Walk(PythonWalker walker) in E:\A\_work\2\s\src\Parsing\Impl\Ast\ImportStatement.cs:line 48
   at Microsoft.Python.Parsing.Ast.SuiteStatement.Walk(PythonWalker walker) in E:\A\_work\2\s\src\Parsing\Impl\Ast\SuiteStatement.cs:line 40
   at Microsoft.Python.Parsing.Ast.PythonAst.Walk(PythonWalker walker) in E:\A\_work\2\s\src\Parsing\Impl\Ast\PythonAst.cs:line 86
   at Microsoft.Python.Analysis.Analyzer.Handlers.LoopImportedVariableHandler.WalkModule(IPythonModule module, PythonAst ast) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\Handlers\LoopImportedVariableHandler.cs:line 123
   at Microsoft.Python.Analysis.Analyzer.PythonAnalyzerSession.AnalyzeLoop(IDependencyChainLoopNode`1 loopNode, Stopwatch stopWatch) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\PythonAnalyzerSession.cs:line 409
   at Microsoft.Python.Analysis.Analyzer.PythonAnalyzerSession.Analyze(IDependencyChainNode node, AsyncCountdownEvent ace, Stopwatch stopWatch) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\PythonAnalyzerSession.cs:line 284
Import:  asn1crypto.keys /opt/alt/python35/lib/python3/dist-packages/asn1crypto/keys.py 
Import:  cryptography.hazmat.primitives.asymmetric.ec /opt/alt/python35/lib/python3/dist-packages/cryptography/hazmat/primitives/asymmetric/ec.py 
Import:  cryptography.hazmat.primitives.asymmetric.rsa /opt/alt/python35/lib/python3/dist-packages/cryptography/hazmat/primitives/asymmetric/rsa.py 
Import:  cryptography.x509.general_name /opt/alt/python35/lib/python3/dist-packages/cryptography/x509/general_name.py 
Analysis of six.moves.cPickle (Stub) queued. Dependencies: pickle (stub)
Analysis version 1387 of 51 entries has started.
[skipped a lot of lines]
Analysis of modules loop [requests(Library), requests.utils(Library), requests.models(Library), requests.api(Library), requests.sessions(Library), requests.auth(Library), requests.adapters(Library)] failed. System.ArgumentNullException: Value cannot be null. (Parameter 'ast')
   at Microsoft.Python.Analysis.Analyzer.Evaluation.ExpressionEval..ctor(IServiceContainer services, IPythonModule module, PythonAst ast) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\Evaluation\ExpressionEval.cs:line 43
   at Microsoft.Python.Analysis.Analyzer.Handlers.LoopImportedVariableHandler.WalkModule(IPythonModule module, PythonAst ast) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\Handlers\LoopImportedVariableHandler.cs:line 119
   at Microsoft.Python.Analysis.Analyzer.Handlers.LoopImportedVariableHandler.WalkModule(IPythonModule module, PythonAst ast) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\Handlers\LoopImportedVariableHandler.cs:line 118
   at Microsoft.Python.Analysis.Analyzer.Handlers.LoopImportedVariableHandler.EnsureModule(IPythonModule& module) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\Handlers\LoopImportedVariableHandler.cs:line 104
   at Microsoft.Python.Analysis.Analyzer.Handlers.LoopImportedVariableHandler.EnsureModule(PythonVariableModule& variableModule) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\Handlers\LoopImportedVariableHandler.cs:line 94
   at Microsoft.Python.Analysis.Analyzer.Handlers.LoopImportedVariableHandler.Microsoft.Python.Analysis.Analyzer.Handlers.IImportedVariableHandler.EnsureModule(PythonVariableModule& module)
   at Microsoft.Python.Analysis.Analyzer.Handlers.ImportHandler.AssignVariables(FromImportStatement node, IImportSearchResult imports, PythonVariableModule variableModule) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\Handlers\FromImportHandler.cs:line 76
   at Microsoft.Python.Analysis.Analyzer.Handlers.ImportHandler.HandleFromImport(FromImportStatement node) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\Handlers\FromImportHandler.cs:line 45
   at Microsoft.Python.Analysis.Analyzer.AnalysisWalker.Walk(FromImportStatement node) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\AnalysisWalker.cs:line 81
   at Microsoft.Python.Parsing.Ast.FromImportStatement.Walk(PythonWalker walker) in E:\A\_work\2\s\src\Parsing\Impl\Ast\FromImportStatement.cs:line 58
   at Microsoft.Python.Parsing.Ast.SuiteStatement.Walk(PythonWalker walker) in E:\A\_work\2\s\src\Parsing\Impl\Ast\SuiteStatement.cs:line 40
   at Microsoft.Python.Parsing.Ast.PythonAst.Walk(PythonWalker walker) in E:\A\_work\2\s\src\Parsing\Impl\Ast\PythonAst.cs:line 86
   at Microsoft.Python.Analysis.Analyzer.Handlers.LoopImportedVariableHandler.WalkModule(IPythonModule module, PythonAst ast) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\Handlers\LoopImportedVariableHandler.cs:line 123
   at Microsoft.Python.Analysis.Analyzer.PythonAnalyzerSession.AnalyzeLoop(IDependencyChainLoopNode`1 loopNode, Stopwatch stopWatch) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\PythonAnalyzerSession.cs:line 409
   at Microsoft.Python.Analysis.Analyzer.PythonAnalyzerSession.Analyze(IDependencyChainNode node, AsyncCountdownEvent ace, Stopwatch stopWatch) in E:\A\_work\2\s\src\Analysis\Ast\Impl\Analyzer\PythonAnalyzerSession.cs:line 284

Full log
[Info - 10:44:22 AM] Analysis cache path: /home/pz/.cache/Microsoft/Python Lang - Pastebin.com

Code Snippet / Additional lnformation

[MikhailArkhipov]

This should be fixed by #1757 in 0.5. Could you try daily

"python.analysis.downloadChannel": "daily"

[zztalker]

This should be fixed by #1757 in 0.5. Could you try daily

"python.analysis.downloadChannel": "daily"

This doesn't help. I've not seen in log exceptions but [Analyzing in the background, 3 items left ] not changed for infinity time.

New log here https://drive.google.com/file/d/1Wi_J4iPq1A3hpoY3KeK8ry0ymoGR7-bl/view?usp=sharing

[zztalker]

@MikhailArkhipov I think that it depends on my imported libs because it hangs not always (always on my working repo, wich huge). How could I get a debug the Language Server to understood on which file it catches the infinity loop?

[MikhailArkhipov]

It certainly does depend on libraries. However, it does not necessarily means hang. Sometimes it is a stuck message or analysis completes except couple of modules. Is CPU still getting consumed? Does any editor functionality (hover, completions) are available?

[zztalker]

Yep, it is continuously consuming CPU. What could I do from my side to help improve PLS?

hover works well, the outline is shown for files except one from which I've started (if start editing file it also fills outline section), completions work well (on current version 0.5.7, on early versions I experienced a problem with it).

[MikhailArkhipov]

Analysis would consume quite a bit more than 1.3%, it runs multiple tasks on multiple cores. Generally LS is not inactive when there is at least some activity in VS Code. Typing re-runs analysis incrementally on changed files and its dependents. Hover also cost a bit of CPU although not much. Or does it spike to 10-20% or higher?

[zztalker]

Hmm, as I see CPU consumption came from vs-code process.

[jakebailey]

If it's VS Code itself, then it's probably out of our control. You should be able to go into "Help > Open Process Explorer" to see what part of VS Code is using the CPU.

[zztalker]

I've done some exploration and discovered that if I open just part of my workspace (separate folder - for example) everything works.

The process explorer does not show anything interesting. (On screenshot I've just started VSCode in problem workspace with opened problem file, [Analyzing in background, 2 items left...] - infinitely showing.

[jakebailey]

Based on that screenshot, htop is saying that it's the GPU process that's eating CPU. I really don't think that can be related to something that the LS is doing; we can't do anything about VS Code's CPU usage. The only thing we can look into is the hanging you've reported.

The only thing I can see in your logs is a reload during the analysis, so I would also consider setting "python.analysis.watchSearchPaths": false and seeing if that changes anything.

[MikhailArkhipov]

Sounds like electron issue to me. I'd suggest reporting to vscode repo, there are some CPU/GPU issues there.

[MikhailArkhipov]

File watch turned off by default in #1841.
LS 0.5.10+