{"action":"opened","issue":{"url":"https://api.github.com/repos/pantsbuild/pants/issues/3416","repository_url":"https://api.github.com/repos/pantsbuild/pants","labels_url":"https://api.github.com/repos/pantsbuild/pants/issues/3416/labels{/name}","comments_url":"https://api.github.com/repos/pantsbuild/pants/issues/3416/comments","events_url":"https://api.github.com/repos/pantsbuild/pants/issues/3416/events","html_url":"https://github.com/pantsbuild/pants/issues/3416","id":154375552,"number":3416,"title":"python task execution can bomb with an unhandled `OSError` when interpreter cache goes stale.","user":{"login":"kwlzn","id":1883523,"avatar_url":"https://avatars.githubusercontent.com/u/1883523?v=3","gravatar_id":"","url":"https://api.github.com/users/kwlzn","html_url":"https://github.com/kwlzn","followers_url":"https://api.github.com/users/kwlzn/followers","following_url":"https://api.github.com/users/kwlzn/following{/other_user}","gists_url":"https://api.github.com/users/kwlzn/gists{/gist_id}","starred_url":"https://api.github.com/users/kwlzn/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/kwlzn/subscriptions","organizations_url":"https://api.github.com/users/kwlzn/orgs","repos_url":"https://api.github.com/users/kwlzn/repos","events_url":"https://api.github.com/users/kwlzn/events{/privacy}","received_events_url":"https://api.github.com/users/kwlzn/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":0,"created_at":"2016-05-12T01:03:07Z","updated_at":"2016-05-12T01:03:07Z","closed_at":null,"body":"observed by one of our users while attempting a `./pants binary <target>`:\r\n\r\n```\r\n13:33:53 00:00 [main]\r\n               (To run a reporting server: ./pants server)\r\n13:33:53 00:00   [setup]\r\n13:33:53 00:00     [parse]\r\n               Executing tasks in goals: bootstrap -> imports -> unpack-jars -> jvm-platform-validate -> deferred-sources -> compute-buildprops -> gen -> resolve -> resources -> buildprops -> compile -> binary\r\n13:33:53 00:00   [bootstrap]\r\n13:33:53 00:00     [jar-dependency-management]\r\n13:33:54 00:01     [bootstrap-jvm-tools]\r\n13:33:54 00:01     [thriftstore-dep-inject]\r\n13:33:54 00:01     [validate-tags]\r\n13:33:54 00:01     [validate-deps]\r\n13:33:54 00:01     [validate-provides]\r\n13:33:54 00:01   [imports]\r\n13:33:54 00:01     [ivy-imports]\r\n13:33:54 00:01   [unpack-jars]\r\n13:33:54 00:01     [unpack-jars]\r\n13:33:54 00:01   [jvm-platform-validate]\r\n13:33:54 00:01     [jvm-platform-validate]\r\n13:33:54 00:01   [deferred-sources]\r\n13:33:54 00:01     [deferred-sources]\r\n13:33:54 00:01   [compute-buildprops]\r\n13:33:54 00:01     [compute-buildprops]\r\n13:33:54 00:01   [gen]\r\n13:33:54 00:01     [dataset]\r\n13:33:54 00:01     [thrift-linter]\r\n13:33:54 00:01     [thrift]\r\n13:33:54 00:01     [protoc]\r\n13:33:54 00:01     [antlr]\r\n13:33:54 00:01     [ragel]\r\n13:33:54 00:01     [jaxb]\r\n13:33:54 00:01     [wire]\r\n13:33:54 00:01     [go-thrift]\r\n13:33:54 00:01     [scrooge]\r\n13:33:54 00:01     [thriftstore-dml-gen]\r\n13:33:54 00:01     [bootstrap]\r\n13:33:54 00:01   [resolve]\r\n13:33:54 00:01     [ivy]\r\n13:33:54 00:01     [go]\r\n13:33:54 00:01     [scala-js-compile]\r\n13:33:54 00:01     [scala-js-link]\r\n13:33:54 00:01     [node]\r\n13:33:54 00:01   [resources]\r\n13:33:54 00:01     [prepare]\r\n13:33:54 00:01     [services]\r\n13:33:54 00:01   [buildprops]\r\n13:33:54 00:01     [binary-buildprops]\r\n13:33:54 00:01   [compile]\r\n13:33:54 00:01     [compile-jvm-prep-command]\r\n13:33:54 00:01       [jvm_prep_command]\r\n13:33:54 00:01     [compile-prep-command]\r\n13:33:54 00:01     [compile]\r\n13:33:54 00:01     [zinc]\r\n13:33:54 00:01     [go]\r\n13:33:54 00:01     [gofmt]\r\n13:33:54 00:01     [python-eval]\r\n13:33:54 00:01     [library-buildprops]\r\n13:33:54 00:01   [binary]\r\n13:33:54 00:01     [binary-jvm-prep-command]\r\n13:33:54 00:01       [jvm_prep_command]\r\n13:33:54 00:01     [binary-prep-command]\r\n13:33:54 00:01     [python-binary-create]\r\n13:33:54 00:01       [chroot]\r\n               Waiting for background workers to finish.\r\n13:33:55 00:02   [complete]\r\n               FAILURE\r\n\r\nException caught: (<type 'exceptions.OSError'>)\r\n  File \".bootstrap/_pex/pex.py\", line 317, in execute\r\n    self._wrap_coverage(self._wrap_profiling, self._execute)\r\n  File \".bootstrap/_pex/pex.py\", line 250, in _wrap_coverage\r\n    runner(*args)\r\n  File \".bootstrap/_pex/pex.py\", line 282, in _wrap_profiling\r\n    runner(*args)\r\n  File \".bootstrap/_pex/pex.py\", line 360, in _execute\r\n    return self.execute_entry(self._pex_info.entry_point)\r\n  File \".bootstrap/_pex/pex.py\", line 418, in execute_entry\r\n    runner(entry_point)\r\n  File \".bootstrap/_pex/pex.py\", line 436, in execute_pkg_resources\r\n    runner()\r\n  File \"/Users/$USER/.pex/install/$WHL/pants/bin/pants_exe.py\", line 44, in main\r\n    PantsRunner(exiter).run()\r\n  File \"/Users/$USER/.pex/install/$WHL/pants/bin/pants_runner.py\", line 53, in run\r\n    options_bootstrapper=options_bootstrapper)\r\n  File \"/Users/$USER/.pex/install/$WHL/pants/bin/pants_runner.py\", line 43, in _run\r\n    return LocalPantsRunner(exiter, args, env, options_bootstrapper=options_bootstrapper).run()\r\n  File \"/Users/$USER/.pex/install/$WHL/pants/bin/local_pants_runner.py\", line 49, in run\r\n    self._maybe_profiled(self._run)\r\n  File \"/Users/$USER/.pex/install/$WHL/pants/bin/local_pants_runner.py\", line 46, in _maybe_profiled\r\n    runner()\r\n  File \"/Users/$USER/.pex/install/$WHL/pants/bin/local_pants_runner.py\", line 89, in _run\r\n    result = goal_runner.run()\r\n  File \"/Users/$USER/.pex/install/$WHL/pants/bin/goal_runner.py\", line 335, in run\r\n    result = self._execute_engine()\r\n  File \"/Users/$USER/.pex/install/$WHL/pants/bin/goal_runner.py\", line 324, in _execute_engine\r\n    result = engine.execute(self._context, self._goals)\r\n  File \"/Users/$USER/.pex/install/$WHL/pants/engine/engine.py\", line 26, in execute\r\n    self.attempt(context, goals)\r\n  File \"/Users/$USER/.pex/install/$WHL/pants/engine/round_engine.py\", line 224, in attempt\r\n    goal_executor.attempt(explain)\r\n  File \"/Users/$USER/.pex/install/$WHL/pants/engine/round_engine.py\", line 47, in attempt\r\n    task.execute()\r\n  File \"/Users/$USER/.pex/install/$WHL/pants/backend/python/tasks/python_binary_create.py\", line 39, in execute\r\n    self.create_binary(binary)\r\n  File \"/Users/$USER/.pex/install/$WHL/pants/backend/python/tasks/python_binary_create.py\", line 52, in create_binary\r\n    platforms=binary.platforms) as chroot:\r\n  File \"/opt/twitter_mde/package/python2.7/current/lib/python2.7/contextlib.py\", line 17, in __enter__\r\n    return self.gen.next()\r\n  File \"/Users/$USER/.pex/install/$WHL/pants/backend/python/tasks/python_task.py\", line 175, in temporary_chroot\r\n    extra_requirements, executable_file_content)\r\n  File \"/Users/$USER/.pex/install/$WHL/pants/backend/python/tasks/python_task.py\", line 198, in _build_chroot\r\n    builder.freeze()\r\n  File \"/Users/$USER/.pex/install/$PEX_WHL/pex/pex_builder.py\", line 408, in freeze\r\n    self._precompile_source()\r\n  File \"/Users/$USER/.pex/install/$PEX_WHL/pex/pex_builder.py\", line 332, in _precompile_source\r\n    compiled_relpaths = compiler.compile(self._chroot.path(), source_relpaths)\r\n  File \"/Users/$USER/.pex/install/$PEX_WHL/pex/compiler.py\", line 86, in compile\r\n    stderr=subprocess.PIPE)\r\n  File \"/opt/twitter_mde/package/python2.7/current/lib/python2.7/subprocess.py\", line 710, in __init__\r\n    errread, errwrite)\r\n  File \"/opt/twitter_mde/package/python2.7/current/lib/python2.7/subprocess.py\", line 1335, in _execute_child\r\n    raise child_exception\r\n\r\nException message: [Errno 2] No such file or directory\r\n```\r\n\r\nwhich ended up being the attempted execution of a dangling symlink to the python interpreter as stored in pants' interpreter cache - along the lines of:\r\n\r\n```\r\n>>> os.path.exists(os.readlink('python'))\r\nFalse\r\n>>> subprocess.Popen(['./python', 'blah'], stdout=subprocess.PIPE, stderr=subprocess.PIPE)\r\nTraceback (most recent call last):\r\n  File \"<input>\", line 1, in <module>\r\n  File \"/opt/twitter_mde/package/python2.7/current/lib/python2.7/subprocess.py\", line 710, in __init__\r\n    errread, errwrite)\r\n  File \"/opt/twitter_mde/package/python2.7/current/lib/python2.7/subprocess.py\", line 1335, in _execute_child\r\n    raise child_exception\r\nOSError: [Errno 2] No such file or directory\r\n```\r\n\r\nthe workaround was a `./pants clean-all` which removes the interpreter cache and allows for a clean rebuild without the dangling symlinks.\r\n\r\nI'm thinking this needs two bits of love:\r\n\r\n1) this particular `subprocess.Popen` call in pex's `compiler.py` and potentially wherever else this pattern is repeated should trap `OSError` and surface a more meaningful exception with the execution failure context.\r\n\r\n2) we should do a better job of validating and pruning the interpreter cache run over run to avoid staleness that can cause this in the first place."}}