{"action":"created","issue":{"url":"https://api.github.com/repos/jupyterhub/jupyterhub/issues/1026","repository_url":"https://api.github.com/repos/jupyterhub/jupyterhub","labels_url":"https://api.github.com/repos/jupyterhub/jupyterhub/issues/1026/labels{/name}","comments_url":"https://api.github.com/repos/jupyterhub/jupyterhub/issues/1026/comments","events_url":"https://api.github.com/repos/jupyterhub/jupyterhub/issues/1026/events","html_url":"https://github.com/jupyterhub/jupyterhub/issues/1026","id":214969239,"number":1026,"title":"PAM authentication issues on Debian","user":{"login":"laurikoobas","id":861986,"avatar_url":"https://avatars2.githubusercontent.com/u/861986?v=3","gravatar_id":"","url":"https://api.github.com/users/laurikoobas","html_url":"https://github.com/laurikoobas","followers_url":"https://api.github.com/users/laurikoobas/followers","following_url":"https://api.github.com/users/laurikoobas/following{/other_user}","gists_url":"https://api.github.com/users/laurikoobas/gists{/gist_id}","starred_url":"https://api.github.com/users/laurikoobas/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/laurikoobas/subscriptions","organizations_url":"https://api.github.com/users/laurikoobas/orgs","repos_url":"https://api.github.com/users/laurikoobas/repos","events_url":"https://api.github.com/users/laurikoobas/events{/privacy}","received_events_url":"https://api.github.com/users/laurikoobas/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":5,"created_at":"2017-03-17T10:52:19Z","updated_at":"2017-03-17T14:59:05Z","closed_at":null,"body":"Seems to be broken similar to some older closed issues.\r\n\r\nThe issue: PAM authentication fails.\r\n\r\nThe longer version of the issue - the exact same code for the exact same (test) user works when called with python3, but does not work when called by jupyterhub (0.7.2).\r\n\r\nI have a test user - testuser.\r\nThis is the code that works:\r\n```python\r\nimport pamela\r\n\r\nusername = 'testuser'\r\npassword = 'testuser'\r\nservice = 'login'\r\n\r\ntry:\r\n    print(\"PAM Authentication test. username = {0} and service = {1}\".format(username, service))\r\n    pamela.authenticate(username, password, service)\r\nexcept pamela.PAMError as e:\r\n    print(\"PAM Authentication failed: {0}\".format(e))\r\nelse:\r\n    print(\"success!\")\r\n```\r\n\r\nIt outputs:\r\n```\r\njupyterhub@virtualmachine:/tmp$ python3 pamtest.py\r\nPAM Authentication test. username = testuser and service = login\r\nsuccess!\r\n```\r\n\r\nAnd this is the code that does not work, found (and sligthly modified) in:\r\n/usr/local/lib/python3.4/dist-packages/jupyterhub/auth.py\r\n```python\r\n    def authenticate(self, handler, data):\r\n        \"\"\"Authenticate with PAM, and return the username if login is successful.\r\n\r\n        Return None otherwise.\r\n        \"\"\"\r\n        username = data['username']\r\n        import traceback\r\n        traceback.print_stack()\r\n        try:\r\n            self.log.warning(\"PAM Authentication test. username = %s and service = %s\", username, self.service)\r\n            # pamela.authenticate(username, data['password'], service=self.service)\r\n            pamela.authenticate('testuser', 'testuser', 'login')\r\n        except pamela.PAMError as e:\r\n            if handler is not None:\r\n                self.log.warning(\"PAM Authentication failed (%s@%s): %s\", username, handler.request.remote_ip, e)\r\n            else:\r\n                self.log.warning(\"PAM Authentication failed: %s\", e)\r\n        else:\r\n            return username\r\n```\r\n\r\nThis is the output:\r\n```\r\n[I 2017-03-17 10:32:58.645 JupyterHub app:1485] JupyterHub is now running at http://127.0.0.1:8000/jupyter/\r\n  File \"/usr/local/bin/jupyterhub\", line 4, in <module>\r\n    main()\r\n  File \"/usr/local/lib/python3.4/dist-packages/jupyterhub/app.py\", line 1536, in launch_instance\r\n    loop.start()\r\n  File \"/usr/local/lib/python3.4/dist-packages/tornado/ioloop.py\", line 831, in start\r\n    self._run_callback(callback)\r\n  File \"/usr/local/lib/python3.4/dist-packages/tornado/ioloop.py\", line 604, in _run_callback\r\n    ret = callback()\r\n  File \"/usr/local/lib/python3.4/dist-packages/tornado/stack_context.py\", line 275, in null_wrapper\r\n    return fn(*args, **kwargs)\r\n  File \"/usr/local/lib/python3.4/dist-packages/tornado/gen.py\", line 1104, in <lambda>\r\n    self.future, lambda f: self.run())\r\n  File \"/usr/local/lib/python3.4/dist-packages/tornado/gen.py\", line 1024, in run\r\n    yielded = self.gen.send(value)\r\n  File \"/usr/local/lib/python3.4/dist-packages/tornado/http1connection.py\", line 238, in _read_message\r\n    delegate.finish()\r\n  File \"/usr/local/lib/python3.4/dist-packages/tornado/httpserver.py\", line 289, in finish\r\n    self.delegate.finish()\r\n  File \"/usr/local/lib/python3.4/dist-packages/tornado/web.py\", line 2047, in finish\r\n    self.execute()\r\n  File \"/usr/local/lib/python3.4/dist-packages/tornado/web.py\", line 2080, in execute\r\n    **self.path_kwargs)\r\n  File \"/usr/local/lib/python3.4/dist-packages/tornado/gen.py\", line 285, in wrapper\r\n    yielded = next(result)\r\n  File \"/usr/local/lib/python3.4/dist-packages/tornado/web.py\", line 1467, in _execute\r\n    result = method(*self.path_args, **self.path_kwargs)\r\n  File \"/usr/local/lib/python3.4/dist-packages/tornado/gen.py\", line 285, in wrapper\r\n    yielded = next(result)\r\n  File \"/usr/local/lib/python3.4/dist-packages/jupyterhub/handlers/login.py\", line 72, in post\r\n    username = yield self.authenticate(data)\r\n  File \"/usr/local/lib/python3.4/dist-packages/tornado/gen.py\", line 285, in wrapper\r\n    yielded = next(result)\r\n  File \"/usr/local/lib/python3.4/dist-packages/jupyterhub/handlers/base.py\", line 281, in authenticate\r\n    result = yield auth.get_authenticated_user(self, data)\r\n  File \"/usr/local/lib/python3.4/dist-packages/tornado/gen.py\", line 285, in wrapper\r\n    yielded = next(result)\r\n  File \"/usr/local/lib/python3.4/dist-packages/jupyterhub/auth.py\", line 171, in get_authenticated_user\r\n    username = yield self.authenticate(handler, data)\r\n  File \"/usr/local/lib/python3.4/dist-packages/tornado/gen.py\", line 270, in wrapper\r\n    result = func(*args, **kwargs)\r\n  File \"/usr/local/lib/python3.4/dist-packages/jupyterhub/auth.py\", line 470, in authenticate\r\n    traceback.print_stack()\r\n[W 2017-03-17 10:33:06.312 JupyterHub auth:472] PAM Authentication test. username = testuser and service = login\r\n[W 2017-03-17 10:33:09.253 JupyterHub auth:477] PAM Authentication failed (testuser@127.0.0.1): [PAM Error 7] Authentication failure\r\n[D 2017-03-17 10:33:09.253 JupyterHub login:95] Failed login for testuser\r\n```\r\n\r\nSomething fails about how jupyterhub calls it.\r\nThe /var/log/auth.log shows the following:\r\n```\r\nMar 17 03:48:08 virtualmachine unix_chkpwd[35948]: check pass; user unknown\r\nMar 17 03:48:08 virtualmachine unix_chkpwd[35948]: password check failed for user (testuser)\r\nMar 17 03:48:08 virtualmachine python3: pam_unix(login:auth): authentication failure; logname=something uid=1006 euid=1006 tty= ruser= rhost=  user=testuser\r\n```\r\n\r\nI looked into getting the PAM module to output some debug data, but couldn't figure out how to do it."},"comment":{"url":"https://api.github.com/repos/jupyterhub/jupyterhub/issues/comments/287377614","html_url":"https://github.com/jupyterhub/jupyterhub/issues/1026#issuecomment-287377614","issue_url":"https://api.github.com/repos/jupyterhub/jupyterhub/issues/1026","id":287377614,"user":{"login":"laurikoobas","id":861986,"avatar_url":"https://avatars2.githubusercontent.com/u/861986?v=3","gravatar_id":"","url":"https://api.github.com/users/laurikoobas","html_url":"https://github.com/laurikoobas","followers_url":"https://api.github.com/users/laurikoobas/followers","following_url":"https://api.github.com/users/laurikoobas/following{/other_user}","gists_url":"https://api.github.com/users/laurikoobas/gists{/gist_id}","starred_url":"https://api.github.com/users/laurikoobas/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/laurikoobas/subscriptions","organizations_url":"https://api.github.com/users/laurikoobas/orgs","repos_url":"https://api.github.com/users/laurikoobas/repos","events_url":"https://api.github.com/users/laurikoobas/events{/privacy}","received_events_url":"https://api.github.com/users/laurikoobas/received_events","type":"User","site_admin":false},"created_at":"2017-03-17T14:59:05Z","updated_at":"2017-03-17T14:59:05Z","body":"> so as jupyterhub the test script works, then as the same user jupyterhub doesn't?\r\n\r\nSeems to be the case, but I may have more information below.\r\n\r\n> Does it matter which user attempts to login first?\r\n\r\nnope\r\n\r\n> Are you running jupyterhub in the same terminal session where you are running the test, or via systemd/supervisor/etc.?\r\n\r\nWas running everything in terminal session.\r\n\r\nTried a few more things, just trying to be thorough.\r\nFirst I tried the PAM test from the guide. Entered the correct password first and then incorrect one.\r\n```\r\nlauri@virtualmachine:~$ sudo -u jupyterhub python3 -c \"import pamela, getpass; print(pamela.authenticate('$USER', getpass.getpass()))\"\r\n[sudo] password for lauri:\r\nPassword:\r\nNone\r\nlauri@virtualmachine:~$ sudo -u jupyterhub python3 -c \"import pamela, getpass; print(pamela.authenticate('$USER', getpass.getpass()))\"\r\nPassword:\r\nTraceback (most recent call last):\r\n  File \"<string>\", line 1, in <module>\r\n  File \"/usr/local/lib/python3.4/dist-packages/pamela.py\", line 285, in authenticate\r\n    return pam_end(handle, retval)\r\n  File \"/usr/local/lib/python3.4/dist-packages/pamela.py\", line 244, in pam_end\r\n    raise PAMError(errno=retval)\r\npamela.PAMError: [PAM Error 7] Authentication failure\r\n```\r\nSo I guess that works as expected?\r\n\r\nThen I ran JupyterHub through sudo like this:\r\n```\r\nsudo -u jupyterhub jupyterhub -f /etc/jupyterhub/jupyterhub_config.py --debug\r\n```\r\nAnd tried to log in with jupyterhub (*with c.PAMAuthenticator.open_sessions = False*)\r\n```\r\n[I 2017-03-17 14:43:08.129 JupyterHub log:100] 200 GET /jupyter/hub/login (@127.0.0.1) 5.97ms\r\n[W 2017-03-17 14:43:09.928 JupyterHub auth:472] PAM Authentication test. username = jupyterhub and service = login\r\n[I 170317 14:43:10 mediator:75] Spawning /usr/local/bin/jupyterhub-singleuser '--user=\"jupyterhub\"' '--cookie-name=\"jupyter-hub-token-jupyterhub\"' '--base-url=\"/jupyter/user/jupyterhub\"' '--hub-host=\"\"' '--hub-prefix=\"/jupyter/hub/\"' '--hub-api-url=\"http://127.0.0.1:8081/jupyter/hub/api\"' '--ip=\"127.0.0.1\"' --port=55075\r\n[W 2017-03-17 14:43:10.828 jupyterhub notebookapp:256] Widgets are unavailable. Please install widgetsnbextension or ipywidgets 4.0\r\n[W 2017-03-17 14:43:10.835 jupyterhub login:222] All authentication is disabled.  Anyone who can connect to this server will be able to run code.\r\n[I 2017-03-17 14:43:10.840 jupyterhub notebookapp:1201] Serving notebooks from local directory: /home/jupyterhub\r\n[I 2017-03-17 14:43:10.840 jupyterhub notebookapp:1201] 0 active kernels\r\n[I 2017-03-17 14:43:10.841 jupyterhub notebookapp:1201] The Jupyter Notebook is running at: http://127.0.0.1:55075/jupyter/user/jupyterhub/\r\n[I 2017-03-17 14:43:10.841 jupyterhub notebookapp:1202] Use Control-C to stop this server and shut down all kernels (twice to skip confirmation).\r\n[D 2017-03-17 14:43:11.127 JupyterHub spawner:584] Polling subprocess every 30s\r\n[I 2017-03-17 14:43:11.139 jupyterhub log:47] 302 GET /jupyter/user/jupyterhub (127.0.0.1) 0.57ms\r\n[D 2017-03-17 14:43:11.140 JupyterHub utils:84] Server at http://127.0.0.1:55075/jupyter/user/jupyterhub responded with 302\r\n[I 2017-03-17 14:43:11.140 JupyterHub base:322] User jupyterhub server took 1.202 seconds to start\r\n[I 2017-03-17 14:43:11.140 JupyterHub orm:188] Adding user jupyterhub to proxy /jupyter/user/jupyterhub => http://127.0.0.1:55075\r\n[D 2017-03-17 14:43:11.142 JupyterHub orm:146] Fetching POST http://127.0.0.1:8001/api/routes/jupyter/user/jupyterhub\r\n[D 2017-03-17 14:43:11.145 JupyterHub base:236] Setting cookie for jupyterhub: jupyter-hub-token-jupyterhub, {}\r\n[D 2017-03-17 14:43:11.148 JupyterHub base:236] Setting cookie for jupyterhub: jupyter-hub-token, {}\r\n[I 2017-03-17 14:43:11.151 JupyterHub log:100] 302 POST /jupyter/hub/login?next= (@127.0.0.1) 1221.47ms\r\n[I 2017-03-17 14:43:11.151 JupyterHub login:91] User logged in: jupyterhub\r\n```\r\nAnd it's a success! I can see the admin panel and whatnot.\r\n\r\nThen tried with my test user:\r\n```\r\n[W 2017-03-17 14:48:56.032 JupyterHub auth:472] PAM Authentication test. username = testuser and service = login\r\nsudo: a password is required\r\n[E 2017-03-17 14:48:56.072 JupyterHub user:251] Unhandled error starting testuser's server: substring not found\r\n[E 2017-03-17 14:48:56.085 JupyterHub web:1548] Uncaught exception POST /jupyter/hub/login?next= (127.0.0.1)\r\n    HTTPServerRequest(protocol='http', host='blaah', method='POST', uri='/jupyter/hub/login?next=', version='HTTP/1.1', remote_ip='127.0.0.1', headers={blaah}})\r\n    Traceback (most recent call last):\r\n      File \"/usr/local/lib/python3.4/dist-packages/tornado/web.py\", line 1469, in _execute\r\n        result = yield result\r\n      File \"/usr/local/lib/python3.4/dist-packages/jupyterhub/handlers/login.py\", line 84, in post\r\n        yield self.spawn_single_user(user)\r\n      File \"/usr/local/lib/python3.4/dist-packages/jupyterhub/handlers/base.py\", line 328, in spawn_single_user\r\n        yield gen.with_timeout(timedelta(seconds=self.slow_spawn_timeout), f)\r\n      File \"/usr/local/lib/python3.4/dist-packages/jupyterhub/user.py\", line 261, in spawn\r\n        raise e\r\n      File \"/usr/local/lib/python3.4/dist-packages/jupyterhub/user.py\", line 229, in spawn\r\n        ip_port = yield gen.with_timeout(timedelta(seconds=spawner.start_timeout), f)\r\n      File \"/usr/local/lib/python3.4/dist-packages/sudospawner/spawner.py\", line 83, in start\r\n        reply = yield self.do(action='spawn', args=self.get_args(), env=self.get_env())\r\n      File \"/usr/local/lib/python3.4/dist-packages/sudospawner/spawner.py\", line 69, in do\r\n        data_str = data_str[data_str.index('{'):data_str.rindex('}')+1]\r\n    ValueError: substring not found\r\n\r\n[D 2017-03-17 14:48:56.087 JupyterHub base:462] No template for 500\r\n[E 2017-03-17 14:48:56.090 JupyterHub log:99] {\r\n      \"X-Forwarded-Port\": \"80\",\r\n      .....\r\n      \"Connection\": \"close\",\r\n    }\r\n[E 2017-03-17 14:48:56.091 JupyterHub log:100] 500 POST /jupyter/hub/login?next= (@127.0.0.1) 57.35ms\r\n\r\n``` \r\n\r\nThen I re-did the same login trials with *c.PAMAuthenticator.open_sessions = TRUE*.\r\nThe results were the same (jupyterhub success, testuser failure), but some extra information appeared in BOTH cases the log like shown below:\r\n```\r\n[W 2017-03-17 14:53:12.664 JupyterHub auth:472] PAM Authentication test. username = testuser and service = login\r\nLinux virtualmachine 3.16.0-4-amd64 #1 SMP Debian 3.16.36-1+deb8u2 (2016-10-19) x86_64\r\n\r\nThe programs included with the Debian GNU/Linux system are free software;\r\nthe exact distribution terms for each program are described in the\r\nindividual files in /usr/share/doc/*/copyright.\r\n\r\nDebian GNU/Linux comes with ABSOLUTELY NO WARRANTY, to the extent\r\npermitted by applicable law.\r\n[W 2017-03-17 14:53:12.706 JupyterHub auth:490] Failed to open PAM session for testuser: [PAM Error 14] Cannot make/remove an entry for the specified session\r\n[W 2017-03-17 14:53:12.706 JupyterHub auth:491] Disabling PAM sessions from now on.\r\nsudo: a password is required\r\n[E 2017-03-17 14:53:12.723 JupyterHub user:251] Unhandled error starting testuser's server: substring not found\r\n```"}}
{"actor":{"display_login":"laurikoobas"}}