Enters infinite loop when home folder contains cyclic symlinks

[sin-ack]

Describe the bug
My home folder contains Proton (from Steam) and Wine. Wine symlinks the dosdevices/z: folder back to /, to provide Windows applications with access to my home filesystem. When Pyright is run and completion is requested, it scans my home folder, eventually reaching the .wine folder, and then infinitely loops trying to read z: (which is /).

To Reproduce

1. Have Wine installed and set up (run winecfg at least once)
2. Start the Pyright language server via your editor
3. Try to complete

Expected behavior
To not infinitely loop.

Editor & OS information
Editor: GNU Emacs 27.1
LSP Plugin: lsp-mode 20210402.1701 + lsp-pyright
OS: Debian GNU/Linux bullseye/testing

[erictraut]

Huh, Pyright contains logic that specifically protects against cyclic symlinks. @jakebailey, any ideas here?

[erictraut]

@sin-ack, what version of pyright are you using? A bug was fixed in version 1.1.123 specifically to handle cyclical symlinks. The latest version is 1.1.128.

[erictraut]

I've tried to repro by manually creating cyclical symlinks in a local project, and the latest version of pyright handles it fine. My best theory is that you're running an old version of pyright.

[jakebailey]

The only think I can think of here is that the realpath syscall when applied to wine's filesystem does not return a consistent result when going across filesystems, and defeats the checks we do to prevent loops. Or, because Z: is literally /, it's so huge that we aren't looping at all, but are taking a load of time.

I guess I'm more wondering why you'd want to open up your entire home folder as a workspace. I can't imagine that going well for exactly these sorts of reasons...

[sin-ack]

@erictraut I am indeed running 1.1.128.

@jakebailey I ran strace on pyright, and could see it running openat on /home/myuser/.local/share/Steam/..more folders here.../dosdevices/z: repeatedly. So I do believe it is looping.

Regarding the workspace comment... I did some digging. lsp-mode seems to have this weird "session" thing, and somehow my home directory got into those "session folders" and got associated with Pyright, which caused the weird behavior seen here. The infinite loop thing is only a side effect, Emacs would freeze up trying to tally the file count so it could warn you that the folder is too big as well (my ~ contains about 1.7 million files from various large projects). I'm guessing it has something to do with multi-root workspaces (which I don't know anything about), but after clearing the "LSP session" thingy, Pyright started working fine. I will keep the issue open, and will try to see whether I can reproduce this bug on a smaller scale (so symlinking inside a small project instead of my whole ~).

[jakebailey]

To be clear, do you see dosdevices repeating in those path names? Or is it just a really path that ends in dosdevices and such?

[sin-ack]

Here's a partial log of strace from the pyright process:

...
lstat("/home", {st_mode=S_IFDIR|0755, st_size=34, ...}) = 0
lstat("/home/myuser", {st_mode=S_IFDIR|0755, st_size=8796, ...}) = 0
lstat("/home/myuser/.local", {st_mode=S_IFDIR|0755, st_size=82, ...}) = 0
lstat("/home/myuser/.local/share", {st_mode=S_IFDIR|0755, st_size=1386, ...}) = 0
lstat("/home/myuser/.local/share/Steam", {st_mode=S_IFDIR|0700, st_size=1154, ...}) = 0
lstat("/home/myuser/.local/share/Steam/steamapps", {st_mode=S_IFDIR|0755, st_size=452, ...}) = 0
lstat("/home/myuser/.local/share/Steam/steamapps/common", {st_mode=S_IFDIR|0755, st_size=218, ...}) = 0
lstat("/home/myuser/.local/share/Steam/steamapps/common/Proton 3.7", {st_mode=S_IFDIR|0755, st_size=272, ...}) = 0
lstat("/home/myuser/.local/share/Steam/steamapps/common/Proton 3.7/dist", {st_mode=S_IFDIR|0755, st_size=46, ...}) = 0
lstat("/home/myuser/.local/share/Steam/steamapps/common/Proton 3.7/dist/share", {st_mode=S_IFDIR|0755, st_size=54, ...}) = 0
lstat("/home/myuser/.local/share/Steam/steamapps/common/Proton 3.7/dist/share/default_pfx", {st_mode=S_IFDIR|0755, st_size=126, ...}) = 0
lstat("/home/myuser/.local/share/Steam/steamapps/common/Proton 3.7/dist/share/default_pfx/dosdevices", {st_mode=S_IFDIR|0755, st_size=40, ...}) = 0
lstat("/home/myuser/.local/share/Steam/steamapps/common/Proton 3.7/dist/share/default_pfx/dosdevices/z:", {st_mode=S_IFLNK|0777, st_size=1, ...}) = 0
stat("/home/myuser/.local/share/Steam/steamapps/common/Proton 3.7/dist/share/default_pfx/dosdevices/z:", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
readlink("/home/myuser/.local/share/Steam/steamapps/common/Proton 3.7/dist/share/default_pfx/dosdevices/z:", "/", 4096) = 1
lstat("/home", {st_mode=S_IFDIR|0755, st_size=34, ...}) = 0
lstat("/home/myuser", {st_mode=S_IFDIR|0755, st_size=8796, ...}) = 0
lstat("/home/myuser/.local", {st_mode=S_IFDIR|0755, st_size=82, ...}) = 0
lstat("/home/myuser/.local/share", {st_mode=S_IFDIR|0755, st_size=1386, ...}) = 0
lstat("/home/myuser/.local/share/Steam", {st_mode=S_IFDIR|0700, st_size=1154, ...}) = 0
lstat("/home/myuser/.local/share/Steam/steamapps", {st_mode=S_IFDIR|0755, st_size=452, ...}) = 0
lstat("/home/myuser/.local/share/Steam/steamapps/common", {st_mode=S_IFDIR|0755, st_size=218, ...}) = 0
lstat("/home/myuser/.local/share/Steam/steamapps/common/Proton 3.7", {st_mode=S_IFDIR|0755, st_size=272, ...}) = 0
lstat("/home/myuser/.local/share/Steam/steamapps/common/Proton 3.7/dist", {st_mode=S_IFDIR|0755, st_size=46, ...}) = 0
lstat("/home/myuser/.local/share/Steam/steamapps/common/Proton 3.7/dist/share", {st_mode=S_IFDIR|0755, st_size=54, ...}) = 0
lstat("/home/myuser/.local/share/Steam/steamapps/common/Proton 3.7/dist/share/default_pfx", {st_mode=S_IFDIR|0755, st_size=126, ...}) = 0
lstat("/home/myuser/.local/share/Steam/steamapps/common/Proton 3.7/dist/share/default_pfx/dosdevices", {st_mode=S_IFDIR|0755, st_size=40, ...}) = 0
lstat("/home/myuser/.local/share/Steam/steamapps/common/Proton 3.7/dist/share/default_pfx/dosdevices/z:", {st_mode=S_IFLNK|0777, st_size=1, ...}) = 0
stat("/home/myuser/.local/share/Steam/steamapps/common/Proton 3.7/dist/share/default_pfx/dosdevices/z:", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
readlink("/home/myuser/.local/share/Steam/steamapps/common/Proton 3.7/dist/share/default_pfx/dosdevices/z:", "/", 4096) = 1
readlink("/sys/class/block/sdb", "../../devices/pci0000:00/0000:00"..., 4096) = 98
lstat("/sys/devices/pci0000:00", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/devices/pci0000:00/0000:00:1a.0", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/devices/pci0000:00/0000:00:1a.0/usb1", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4/1-1.4:1.0", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4/1-1.4:1.0/host6", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4/1-1.4:1.0/host6/target6:0:0", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4/1-1.4:1.0/host6/target6:0:0/6:0:0:0", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4/1-1.4:1.0/host6/target6:0:0/6:0:0:0/block", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4/1-1.4:1.0/host6/target6:0:0/6:0:0:0/block/sdb", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4/1-1.4:1.0/host6/target6:0:0/6:0:0:0/block/sdb/device", {st_mode=S_IFLNK|0777, st_size=0, ...}) = 0
stat("/sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4/1-1.4:1.0/host6/target6:0:0/6:0:0:0/block/sdb/device", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
readlink("/sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4/1-1.4:1.0/host6/target6:0:0/6:0:0:0/block/sdb/device", "../../../6:0:0:0", 4096) = 16
lstat("/sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4/1-1.4:1.0/host6/target6:0:0/6:0:0:0/scsi_generic", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4/1-1.4:1.0/host6/target6:0:0/6:0:0:0/scsi_generic/sg2", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat("/sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4/1-1.4:1.0/host6/target6:0:0/6:0:0:0/scsi_generic/sg2/subsystem", {st_mode=S_IFLNK|0777, st_size=0, ...}) = 0
stat("/sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4/1-1.4:1.0/host6/target6:0:0/6:0:0:0/scsi_generic/sg2/subsystem", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
readlink("/sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.4/1-1.4:1.0/host6/target6:0:0/6:0:0:0/scsi_generic/sg2/subsystem", "../../../../../../../../../../.."..., 4096) = 54
...

Seems like any symlink that links above triggers an infinite loop.

[jakebailey]

I guess I'm trying to decide whether or not this is actually looping, or if it's just huge because it hits the filesystem root. I'd think the former case wouldn't occur; our traversal should be remembering the realpath of each folder and checking before it recurses. But, it really should not have continued when it saw /home the second time...

[erictraut]

If these fs accesses are performed by the loop that scans for source files, we should see the string "Skipping recursive symlink" appear in the log output.

I've reviewed all of the other code paths in pyright where we resolve symlinks, and none of them should result in a recursive walk of the file system hierarchy.

My only other thought is that it's a problem with the file watching code.

[jakebailey]

Yeah, I went though too and didn't find anything.

I don't think it'd be the file watching, since we don't actually watch anything in the workspace, and that's where I'm presuming the link begins. I'll have to spin up wine and see for myself.

[sin-ack]

Is there anyway I can provide you with a debug log from my end?

[jakebailey]

I'm unsure how to do this in emacs, but if you can set "python.analysis.logLevel": "Trace", I'd like to see if it's hanging at the point where we scan for source files in the workspace.

[sin-ack]

Here's a log at Trace level. Nothing happens after the last line, and pyright is stuck at 100% CPU.

Trace log

[Trace - 12:13:43 AM] Sending request 'initialize - (91)'.
Params: {
  "processId": null,
  "rootPath": "/home/myuser/projects/myproject",
  "clientInfo": {
    "name": "emacs",
    "version": "GNU Emacs 27.1 (build 1, x86_64-pc-linux-gnu, GTK+ Version 3.24.23, cairo version 1.16.0)\n of 2020-11-08, modified by Debian"
  },
  "rootUri": "file:///home/myuser/projects/myproject",
  "capabilities": {
    "workspace": {
      "workspaceEdit": {
        "documentChanges": true,
        "resourceOperations": [
          "create",
          "rename",
          "delete"
        ]
      },
      "applyEdit": true,
      "symbol": {
        "symbolKind": {
          "valueSet": [
            1,
            2,
            3,
            4,
            5,
            6,
            7,
            8,
            9,
            10,
            11,
            12,
            13,
            14,
            15,
            16,
            17,
            18,
            19,
            20,
            21,
            22,
            23,
            24,
            25,
            26
          ]
        }
      },
      "executeCommand": {
        "dynamicRegistration": false
      },
      "workspaceFolders": true,
      "configuration": true
    },
    "textDocument": {
      "declaration": {
        "linkSupport": true
      },
      "definition": {
        "linkSupport": true
      },
      "implementation": {
        "linkSupport": true
      },
      "typeDefinition": {
        "linkSupport": true
      },
      "synchronization": {
        "willSave": true,
        "didSave": true,
        "willSaveWaitUntil": true
      },
      "documentSymbol": {
        "symbolKind": {
          "valueSet": [
            1,
            2,
            3,
            4,
            5,
            6,
            7,
            8,
            9,
            10,
            11,
            12,
            13,
            14,
            15,
            16,
            17,
            18,
            19,
            20,
            21,
            22,
            23,
            24,
            25,
            26
          ]
        },
        "hierarchicalDocumentSymbolSupport": true
      },
      "formatting": {
        "dynamicRegistration": true
      },
      "rangeFormatting": {
        "dynamicRegistration": true
      },
      "rename": {
        "dynamicRegistration": true,
        "prepareSupport": true
      },
      "codeAction": {
        "dynamicRegistration": true,
        "isPreferredSupport": true,
        "codeActionLiteralSupport": {
          "codeActionKind": {
            "valueSet": [
              "",
              "quickfix",
              "refactor",
              "refactor.extract",
              "refactor.inline",
              "refactor.rewrite",
              "source",
              "source.organizeImports"
            ]
          }
        },
        "resolveSupport": {
          "properties": [
            "edit",
            "command"
          ]
        },
        "dataSupport": true
      },
      "completion": {
        "completionItem": {
          "snippetSupport": true,
          "documentationFormat": [
            "markdown"
          ],
          "resolveAdditionalTextEditsSupport": true,
          "resolveSupport": {
            "properties": [
              "documentation",
              "details",
              "additionalTextEdits",
              "command"
            ]
          }
        },
        "contextSupport": true
      },
      "signatureHelp": {
        "signatureInformation": {
          "parameterInformation": {
            "labelOffsetSupport": true
          }
        }
      },
      "documentLink": {
        "dynamicRegistration": true,
        "tooltipSupport": true
      },
      "hover": {
        "contentFormat": [
          "markdown",
          "plaintext"
        ]
      },
      "foldingRange": null,
      "callHierarchy": {
        "dynamicRegistration": false
      },
      "publishDiagnostics": {
        "relatedInformation": true,
        "tagSupport": {
          "valueSet": [
            1,
            2
          ]
        },
        "versionSupport": true
      }
    },
    "window": {
      "workDoneProgress": true
    }
  },
  "initializationOptions": null,
  "workDoneToken": "1",
  "workspaceFolders": [
    {
      "uri": "file:///home/myuser/projects/myproject",
      "name": "myproject"
    },
    {
      "uri": "file:///home/myuser",
      "name": "myuser"
    }
  ]
}


[Trace - 12:13:43 AM] Received notification 'window/logMessage'.
Params: {
  "message": "Pyright language server 1.1.128 starting",
  "type": 3
}


[Trace - 12:13:43 AM] Received notification 'window/logMessage'.
Params: {
  "message": "Server root directory: /home/myuser/.emacs.d/.local/etc/lsp/npm/pyright/lib/node_modules/pyright/dist/",
  "type": 3
}


[Trace - 12:13:43 AM] Received response 'initialize - (91)' in 215ms.
Result: {
  "capabilities": {
    "callHierarchyProvider": true,
    "executeCommandProvider": {
      "workDoneProgress": true,
      "commands": []
    },
    "codeActionProvider": {
      "workDoneProgress": true,
      "codeActionKinds": [
        "quickfix",
        "source.organizeImports"
      ]
    },
    "signatureHelpProvider": {
      "workDoneProgress": true,
      "triggerCharacters": [
        "(",
        ",",
        ")"
      ]
    },
    "completionProvider": {
      "workDoneProgress": true,
      "resolveProvider": true,
      "triggerCharacters": [
        ".",
        "["
      ]
    },
    "renameProvider": {
      "workDoneProgress": true
    },
    "documentHighlightProvider": {
      "workDoneProgress": true
    },
    "hoverProvider": {
      "workDoneProgress": true
    },
    "workspaceSymbolProvider": {
      "workDoneProgress": true
    },
    "documentSymbolProvider": {
      "workDoneProgress": true
    },
    "referencesProvider": {
      "workDoneProgress": true
    },
    "declarationProvider": {
      "workDoneProgress": true
    },
    "definitionProvider": {
      "workDoneProgress": true
    },
    "textDocumentSync": 2
  }
}


[Trace - 12:13:43 AM] Sending notification 'initialized'.
Params: {
}


[Trace - 12:13:43 AM] Sending notification 'workspace/didChangeConfiguration'.
Params: {
  "settings": {
  }
}


[Trace - 12:13:43 AM] Sending notification 'textDocument/didOpen'.
Params: {
  "textDocument": {
    "uri": "file:///home/myuser/projects/myproject/app/myproject/settings.py",
    "languageId": "python",
    "version": 44,
    "text": "\"\"\"\nDjango settings for myproject project.\n\nGenerated by 'django-admin startproject' using Django 3.1.7.\n\nFor more information on this file, see\nhttps://docs.djangoproject.com/en/3.1/topics/settings/\n\nFor the full list of settings and their values, see\nhttps://docs.djangoproject.com/en/3.1/ref/settings/\n\"\"\"\n\nimport os\nfrom pathlib import Path\n\n\ndef require_env(key: str):\n    \"\"\"Requires that an environment variable is present.\"\"\"\n    # Check if the build environment is enabled, and if so, skip this.\n    if os.getenv(\"ENV\") == \"build\":\n        # SECRET_KEY complains about being empty.\n        return \"build\"\n\n    value = os.getenv(key)\n    if not value:\n        raise ValueError(f\"{key} is not present in the environment, and is required.\")\n    return value\n\n\n# Build paths inside the project like this: BASE_DIR / 'subdir'.\nBASE_DIR = Path(__file__).resolve().parent.parent\n\n# Quick-start development settings - unsuitable for production\n# See https://docs.djangoproject.com/en/3.1/howto/deployment/checklist/\n\n# SECURITY WARNING: keep the secret key used in production secret!\nSECRET_KEY = require_env(\"SECRET_KEY\")\n\n# SECURITY WARNING: don't run with debug turned on in production!\nDEBUG = True\n\nALLOWED_HOSTS = [\"localhost\", \"app\"]\n\n(setq lsp-enable-file-watchers nil)\n(setq lsp-pyright-log-level \"Trace\")\n(setq lsp-io-log t)\n\n# Application definition\n\nINSTALLED_APPS = [\n    \"django.contrib.admin\",\n    \"django.contrib.auth\",\n    \"django.contrib.contenttypes\",\n    \"django.contrib.sessions\",\n    \"django.contrib.messages\",\n    \"django.contrib.staticfiles\",\n]\n\nMIDDLEWARE = [\n    \"django.middleware.security.SecurityMiddleware\",\n    \"django.contrib.sessions.middleware.SessionMiddleware\",\n    \"django.middleware.common.CommonMiddleware\",\n    \"django.middleware.csrf.CsrfViewMiddleware\",\n    \"django.contrib.auth.middleware.AuthenticationMiddleware\",\n    \"django.contrib.messages.middleware.MessageMiddleware\",\n    \"django.middleware.clickjacking.XFrameOptionsMiddleware\",\n]\n\nROOT_URLCONF = \"myproject.urls\"\n\nTEMPLATES = [\n    {\n        \"BACKEND\": \"django.template.backends.django.DjangoTemplates\",\n        \"DIRS\": [],\n        \"APP_DIRS\": True,\n        \"OPTIONS\": {\n            \"context_processors\": [\n                \"django.template.context_processors.debug\",\n                \"django.template.context_processors.request\",\n                \"django.contrib.auth.context_processors.auth\",\n                \"django.contrib.messages.context_processors.messages\",\n            ],\n        },\n    },\n]\n\nWSGI_APPLICATION = \"myproject.wsgi.application\"\n\n\n# Database\n# https://docs.djangoproject.com/en/3.1/ref/settings/#databases\n\nDATABASES = {\n    \"default\": {\n        \"ENGINE\": \"django.db.backends.postgresql\",\n        \"NAME\": require_env(\"PGDATABASE\"),\n        \"USER\": require_env(\"PGUSER\"),\n        \"PASSWORD\": require_env(\"PGPASSWORD\"),\n        \"HOST\": require_env(\"PGHOST\"),\n        \"PORT\": int(os.getenv(\"PGPORT\", \"5432\")),\n    }\n}\n\n\n# Password validation\n# https://docs.djangoproject.com/en/3.1/ref/settings/#auth-password-validators\n\nAUTH_PASSWORD_VALIDATORS = [\n    {\n        \"NAME\": \"django.contrib.auth.password_validation.UserAttributeSimilarityValidator\",\n    },\n    {\n        \"NAME\": \"django.contrib.auth.password_validation.MinimumLengthValidator\",\n    },\n    {\n        \"NAME\": \"django.contrib.auth.password_validation.CommonPasswordValidator\",\n    },\n    {\n        \"NAME\": \"django.contrib.auth.password_validation.NumericPasswordValidator\",\n    },\n]\n\n\n# Internationalization\n# https://docs.djangoproject.com/en/3.1/topics/i18n/\n\nLANGUAGE_CODE = \"en-us\"\n\nTIME_ZONE = \"UTC\"\n\nUSE_I18N = True\n\nUSE_L10N = True\n\nUSE_TZ = True\n\n\n# Static files (CSS, JavaScript, Images)\n# https://docs.djangoproject.com/en/3.1/howto/static-files/\n\nSTATIC_URL = \"/static/\"\nSTATIC_ROOT = \"/app/static/\"\n"
  }
}


[Trace - 12:13:43 AM] Sending request 'textDocument/codeAction - (92)'.
Params: {
  "textDocument": {
    "uri": "file:///home/myuser/projects/myproject/app/myproject/settings.py"
  },
  "range": {
    "start": {
      "line": 45,
      "character": 18
    },
    "end": {
      "line": 45,
      "character": 18
    }
  },
  "context": {
    "diagnostics": []
  }
}


[Trace - 12:13:43 AM] Sending request 'textDocument/documentHighlight - (93)'.
Params: {
  "textDocument": {
    "uri": "file:///home/myuser/projects/myproject/app/myproject/settings.py"
  },
  "position": {
    "line": 45,
    "character": 18
  }
}


[Trace - 12:13:43 AM] Sending request 'textDocument/codeAction - (94)'.
Params: {
  "textDocument": {
    "uri": "file:///home/myuser/projects/myproject/app/myproject/settings.py"
  },
  "range": {
    "start": {
      "line": 45,
      "character": 18
    },
    "end": {
      "line": 45,
      "character": 18
    }
  },
  "context": {
    "diagnostics": []
  }
}


[Trace - 12:13:43 AM] Received request 'client/registerCapability - (0).
Params: {
  "registrations": [
    {
      "registerOptions": {
      },
      "method": "workspace/didChangeWorkspaceFolders",
      "id": "dc5a6d39-69b6-4f6a-a05f-96cd493d65fd"
    }
  ]
}


[Trace - 12:13:43 AM] Sending response 'client/registerCapability - (0)'. Processing request took 2ms
Params: {
  "jsonrpc": "2.0",
  "id": 0,
  "result": null
}


[Trace - 12:13:43 AM] Received request 'workspace/configuration - (1).
Params: {
  "items": [
    {
      "section": "python",
      "scopeUri": "file:///home/myuser/projects/myproject"
    }
  ]
}


[Trace - 12:13:43 AM] Sending response 'workspace/configuration - (1)'. Processing request took 4ms
Params: {
  "jsonrpc": "2.0",
  "id": 1,
  "result": [
    {
      "autoComplete": {
        "extraPaths": [],
        "addBrackets": true
      },
      "venvPath": "",
      "pythonPath": "/home/myuser/projects/myproject/env/bin/python",
      "analysis": {
        "disabled": [],
        "information": [],
        "warnings": [
          "unresolved-import",
          "parameter-already-specified",
          "too-many-positional-arguments-before-star"
        ],
        "errors": [
          "unknown-parameter-name",
          "undefined-variable",
          "parameter-missing",
          "positional-argument-after-keyword",
          "too-many-function-arguments"
        ],
        "cachingLevel": "None",
        "extraPaths": [],
        "autoSearchPaths": true,
        "logLevel": "Trace",
        "typeCheckingMode": "basic",
        "diagnosticMode": "openFilesOnly",
        "useLibraryCodeForTypes": true,
        "stubPath": "",
        "typeshedPaths": [],
        "autoImportCompletions": true
      }
    }
  ]
}


[Trace - 12:13:43 AM] Received request 'workspace/configuration - (2).
Params: {
  "items": [
    {
      "section": "python",
      "scopeUri": "file:///home/myuser"
    }
  ]
}


[Trace - 12:13:43 AM] Sending response 'workspace/configuration - (2)'. Processing request took 4ms
Params: {
  "jsonrpc": "2.0",
  "id": 2,
  "result": [
    {
      "autoComplete": {
        "extraPaths": [],
        "addBrackets": true
      },
      "venvPath": "",
      "pythonPath": "/home/myuser/projects/myproject/env/bin/python",
      "analysis": {
        "disabled": [],
        "information": [],
        "warnings": [
          "unresolved-import",
          "parameter-already-specified",
          "too-many-positional-arguments-before-star"
        ],
        "errors": [
          "unknown-parameter-name",
          "undefined-variable",
          "parameter-missing",
          "positional-argument-after-keyword",
          "too-many-function-arguments"
        ],
        "cachingLevel": "None",
        "extraPaths": [],
        "autoSearchPaths": true,
        "logLevel": "Trace",
        "typeCheckingMode": "basic",
        "diagnosticMode": "openFilesOnly",
        "useLibraryCodeForTypes": true,
        "stubPath": "",
        "typeshedPaths": [],
        "autoImportCompletions": true
      }
    }
  ]
}


[Trace - 12:13:43 AM] Received request 'workspace/configuration - (3).
Params: {
  "items": [
    {
      "section": "python.analysis",
      "scopeUri": "file:///home/myuser/projects/myproject"
    }
  ]
}


[Trace - 12:13:43 AM] Sending response 'workspace/configuration - (3)'. Processing request took 3ms
Params: {
  "jsonrpc": "2.0",
  "id": 3,
  "result": [
    {
      "disabled": [],
      "information": [],
      "warnings": [
        "unresolved-import",
        "parameter-already-specified",
        "too-many-positional-arguments-before-star"
      ],
      "errors": [
        "unknown-parameter-name",
        "undefined-variable",
        "parameter-missing",
        "positional-argument-after-keyword",
        "too-many-function-arguments"
      ],
      "cachingLevel": "None",
      "extraPaths": [],
      "autoSearchPaths": true,
      "logLevel": "Trace",
      "typeCheckingMode": "basic",
      "diagnosticMode": "openFilesOnly",
      "useLibraryCodeForTypes": true,
      "stubPath": "",
      "typeshedPaths": [],
      "autoImportCompletions": true
    }
  ]
}


[Trace - 12:13:43 AM] Received request 'workspace/configuration - (4).
Params: {
  "items": [
    {
      "section": "python.analysis",
      "scopeUri": "file:///home/myuser"
    }
  ]
}


[Trace - 12:13:43 AM] Sending response 'workspace/configuration - (4)'. Processing request took 3ms
Params: {
  "jsonrpc": "2.0",
  "id": 4,
  "result": [
    {
      "disabled": [],
      "information": [],
      "warnings": [
        "unresolved-import",
        "parameter-already-specified",
        "too-many-positional-arguments-before-star"
      ],
      "errors": [
        "unknown-parameter-name",
        "undefined-variable",
        "parameter-missing",
        "positional-argument-after-keyword",
        "too-many-function-arguments"
      ],
      "cachingLevel": "None",
      "extraPaths": [],
      "autoSearchPaths": true,
      "logLevel": "Trace",
      "typeCheckingMode": "basic",
      "diagnosticMode": "openFilesOnly",
      "useLibraryCodeForTypes": true,
      "stubPath": "",
      "typeshedPaths": [],
      "autoImportCompletions": true
    }
  ]
}


[Trace - 12:13:43 AM] Received request 'workspace/configuration - (5).
Params: {
  "items": [
    {
      "section": "pyright",
      "scopeUri": "file:///home/myuser/projects/myproject"
    }
  ]
}


[Trace - 12:13:43 AM] Sending response 'workspace/configuration - (5)'. Processing request took 0ms
Params: {
  "jsonrpc": "2.0",
  "id": 5,
  "result": [
    {
      "disableOrganizeImports": false,
      "disableLanguageServices": false
    }
  ]
}


[Trace - 12:13:43 AM] Received request 'workspace/configuration - (6).
Params: {
  "items": [
    {
      "section": "pyright",
      "scopeUri": "file:///home/myuser"
    }
  ]
}


[Trace - 12:13:43 AM] Sending response 'workspace/configuration - (6)'. Processing request took 1ms
Params: {
  "jsonrpc": "2.0",
  "id": 6,
  "result": [
    {
      "disableOrganizeImports": false,
      "disableLanguageServices": false
    }
  ]
}


[Trace - 12:13:44 AM] Sending notification '$/cancelRequest'.
Params: {
  "id": 92
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "No configuration file found.",
  "type": 3
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "Setting pythonPath for service \"myproject\": \"/home/myuser/projects/myproject/env/bin/python\"",
  "type": 3
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "Search paths found for configured python interpreter:",
  "type": 4
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "  /usr/lib/python3.9",
  "type": 4
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "  /usr/lib/python3.9/lib-dynload",
  "type": 4
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "  /home/myuser/projects/myproject/env/lib/python3.9/site-packages",
  "type": 4
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "stubPath /home/myuser/projects/myproject/typings is not a valid directory.",
  "type": 2
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "Assuming Python version 3.9",
  "type": 3
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "Assuming Python platform Linux",
  "type": 3
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "Exception received when installing recursive file system watcher",
  "type": 1
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "Searching for source files",
  "type": 3
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "Auto-excluding /home/myuser/projects/myproject/env",
  "type": 3
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "Found 14 source files",
  "type": 3
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "[FG] parsing: /home/myuser/projects/myproject/app/myproject/settings.py (80ms)",
  "type": 4
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "[FG] parsing: /home/myuser/.emacs.d/.local/etc/lsp/npm/pyright/lib/node_modules/pyright/dist/typeshed-fallback/stdlib/builtins.pyi [fs read 3ms] (145ms)",
  "type": 4
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "[FG] binding: /home/myuser/.emacs.d/.local/etc/lsp/npm/pyright/lib/node_modules/pyright/dist/typeshed-fallback/stdlib/builtins.pyi (68ms)",
  "type": 4
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "[FG] binding: /home/myuser/projects/myproject/app/myproject/settings.py (2ms)",
  "type": 4
}


[Trace - 12:13:44 AM] Received response 'textDocument/documentHighlight - (93)' in 193ms.
Result: null


[Trace - 12:13:44 AM] Received response 'nil - (92)' in 0ms.
Result: []


[Trace - 12:13:44 AM] Received response 'textDocument/codeAction - (94)' in 190ms.
Result: []


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "[FG] analyzing: /home/myuser/projects/myproject/app/myproject/settings.py ...",
  "type": 4
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "[FG]   checking: /home/myuser/projects/myproject/app/myproject/settings.py ...",
  "type": 4
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "[FG]     parsing: /home/myuser/.emacs.d/.local/etc/lsp/npm/pyright/lib/node_modules/pyright/dist/typeshed-fallback/stdlib/_typeshed/__init__.pyi [fs read 1ms] (16ms)",
  "type": 4
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "[FG]     binding: /home/myuser/.emacs.d/.local/etc/lsp/npm/pyright/lib/node_modules/pyright/dist/typeshed-fallback/stdlib/_typeshed/__init__.pyi (3ms)",
  "type": 4
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "[FG]     parsing: /home/myuser/.emacs.d/.local/etc/lsp/npm/pyright/lib/node_modules/pyright/dist/typeshed-fallback/stdlib/typing.pyi [fs read 1ms] (37ms)",
  "type": 4
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "[FG]     binding: /home/myuser/.emacs.d/.local/etc/lsp/npm/pyright/lib/node_modules/pyright/dist/typeshed-fallback/stdlib/typing.pyi (18ms)",
  "type": 4
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "[FG]     parsing: /home/myuser/.emacs.d/.local/etc/lsp/npm/pyright/lib/node_modules/pyright/dist/typeshed-fallback/stubs/typing-extensions/typing_extensions.pyi [fs read 2ms] (7ms)",
  "type": 4
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "[FG]     binding: /home/myuser/.emacs.d/.local/etc/lsp/npm/pyright/lib/node_modules/pyright/dist/typeshed-fallback/stubs/typing-extensions/typing_extensions.pyi (7ms)",
  "type": 4
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "[FG]     parsing: /home/myuser/.emacs.d/.local/etc/lsp/npm/pyright/lib/node_modules/pyright/dist/typeshed-fallback/stdlib/os/__init__.pyi [fs read 0ms] (28ms)",
  "type": 4
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "[FG]     binding: /home/myuser/.emacs.d/.local/etc/lsp/npm/pyright/lib/node_modules/pyright/dist/typeshed-fallback/stdlib/os/__init__.pyi (22ms)",
  "type": 4
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "[FG]     parsing: /home/myuser/.emacs.d/.local/etc/lsp/npm/pyright/lib/node_modules/pyright/dist/typeshed-fallback/stdlib/pathlib.pyi [fs read 1ms] (5ms)",
  "type": 4
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "[FG]     binding: /home/myuser/.emacs.d/.local/etc/lsp/npm/pyright/lib/node_modules/pyright/dist/typeshed-fallback/stdlib/pathlib.pyi (9ms)",
  "type": 4
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "[FG]     parsing: /home/myuser/.emacs.d/.local/etc/lsp/npm/pyright/lib/node_modules/pyright/dist/typeshed-fallback/stdlib/abc.pyi [fs read 0ms] (1ms)",
  "type": 4
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "[FG]     binding: /home/myuser/.emacs.d/.local/etc/lsp/npm/pyright/lib/node_modules/pyright/dist/typeshed-fallback/stdlib/abc.pyi (0ms)",
  "type": 4
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "[FG]   checking: /home/myuser/projects/myproject/app/myproject/settings.py (238ms)",
  "type": 4
}


[Trace - 12:13:44 AM] Received notification 'window/logMessage'.
Params: {
  "message": "[FG] analyzing: /home/myuser/projects/myproject/app/myproject/settings.py (238ms)",
  "type": 4
}


[Trace - 12:13:44 AM] Received notification 'textDocument/publishDiagnostics'.
Params: {
  "diagnostics": [
    {
      "source": "Pyright",
      "severity": 1,
      "message": "Expected \")\"",
      "range": {
        "end": {
          "character": 9,
          "line": 43
        },
        "start": {
          "character": 6,
          "line": 43
        }
      }
    },
    {
      "source": "Pyright",
      "severity": 1,
      "message": "Expected \")\"",
      "range": {
        "end": {
          "character": 9,
          "line": 44
        },
        "start": {
          "character": 6,
          "line": 44
        }
      }
    },
    {
      "source": "Pyright",
      "severity": 1,
      "message": "Expected \")\"",
      "range": {
        "end": {
          "character": 9,
          "line": 45
        },
        "start": {
          "character": 6,
          "line": 45
        }
      }
    }
  ],
  "uri": "file:///home/myuser/projects/myproject/app/myproject/settings.py"
}


[Trace - 12:13:53 AM] Sending request 'textDocument/codeAction - (95)'.
Params: {
  "textDocument": {
    "uri": "file:///home/myuser/projects/myproject/app/myproject/settings.py"
  },
  "range": {
    "start": {
      "line": 45,
      "character": 18
    },
    "end": {
      "line": 45,
      "character": 18
    }
  },
  "context": {
    "diagnostics": [
      {
        "source": "Pyright",
        "severity": 1,
        "message": "Expected \")\"",
        "range": {
          "end": {
            "character": 9,
            "line": 45
          },
          "start": {
            "character": 6,
            "line": 45
          }
        }
      }
    ]
  }
}

[jakebailey]

That's the LSP trace, but the logs I'm in interested are our own log messages (those sent with window/logMessage), but I can mostly see them though the noise. If you can get those directly that'd be preferred for the future if possible.

Anyway, extracting out some bits:

Exception received when installing recursive file system watcher
Searching for source files
Auto-excluding /home/myuser/projects/myproject/env
Found 14 source files
[FG] parsing: /home/myuser/projects/myproject/app/myproject/settings.py (80ms)
...

It's not stalling during the source file search, so this would seem to be elsewhere. An exception occurs when installing the file watcher, so that's a bit concerning (we should probably print that), but in that case there wouldn't be a file watcher, so I'm at a loss as to which code comes next that can be getting stuck.

[sin-ack]

I will try to profile the pyright process on my own end. Since it's (presumably) infinite looping in Node code, that might help me see which code paths are the hottest, which should reveal what's causing the loop.

[jakebailey]

If you can manage that, that'd be most welcome.

[erictraut]

@sin-ack, any update on this issue?

[sin-ack]

I am sorry, I'm currently very busy with work. I'll try to return to this after Monday.

[erictraut]

@sin-ack, any more clues on this one?

[erictraut]

I'm going to close this issue since we haven't heard anything in over two weeks. If you are still able to repro the problem and have additional clues, please post them here, and we'll re-open the issue.

[m-khvoinitsky]

I do experience the same problem with Emacs + lsp-mode and latest pyright (freshly built from git b882b9c).
Attaching node profile.

[cantao]

I do experience the same problem with Emacs + lsp-mode and latest pyright (freshly built from git b882b9c).

Same here (Spacemacs with lsp-mode), pyright installed with npm install -g pyright (1.1.138).

[jakebailey]

Some logs would be very helpful to identify if this is still in the source file scanning part of the code.

Unfortunately the above profile didn't really help, other than to say that a good amount of CPU time is spent asking the FS for the realpath of things (which is sort of expected, but maybe not to that degree). I think the kind of profile that would work best is the one that the Chrome DevTools captures, versus node's built-in trace (which just shows the top entries).

[cantao]

In my case I nailed down the problem to importmagic. Uninstalled it and everything is working fine now. Thank you very much!

[erictraut]

@jakebailey, based on the profiles provided by @m-khvoinitsky, it's pretty clear that the time is being spent in the code that searches for source files (in the _matchFiles function). I've reviewed that code, and I don't see any way that we would recurse indefinitely. My best guess is that someone has created a symbolic link to the root of the drive, and we're scanning the entire drive for python sources.

If my hypothesis is correct, this isn't really a bug in pyright, but there are things we could do to help protect against this situation — or at least make it more diagnosable.

1. We could detect the case where a symlink refers to a root directory and either terminate the scan or log a message indicating that we found such a symlink so it can be fixed by the user.
2. We could detect any case where a symlink takes us to a path outside of the workspace root and terminate the scan. I think this is justified given that the include file specs are intended to be relative to (and contained within) the workspace.

Thoughts?

[jakebailey]

I think both are a good idea, and I'd probably want to expand 1) to maybe print all symlinks in trace mode for better info.

I'd want to wait to try and touch this until after today's release, though. Too little time for testing. 🙂

[jakebailey]

The latter case might be a bit incongruent with how VS Code treats symlinks, though; I'd want to test that out to see if VS Code presents symlinks as folders when they aren't within the workspace.

[m-khvoinitsky]

My best guess is that someone has created a symbolic link to the root of the drive, and we're scanning the entire drive for python sources.

It looks like

$ find -type l -exec bash -c '[[ "$(readlink -f "$0")" == / ]] && echo "$0"' '{}' \;
./.wine/dosdevices/z:

Makes sense because it is exactly what is written in the very first comment. :)

[jakebailey]

Right, yeah.

Has there been any insight into why your editor is trying to make your home directory a workspace? It'd be good to try and fix this, but I would also expect that opening a giant folder wouldn't be such a good idea either, and your previous comments implied it was an editor bug.

[erictraut]

Based on the evidence from this thread, this is not a bug. Pyright is handling cyclic symlinks correct. The same behavior would occur if you attempted to open the root of your drive or your home directory as a workspace. I'm therefore going to close the bug report.