Bug on Playlist Creation

abrahampost commented 6 years ago

Describe the bug Occasionally upon requesting a new Playlist made the server will respond with a 500 error, and report an issue in the console. No playlist is made, and the frontend correctly reports the error.

To Reproduce Steps to reproduce the behavior: Unfortunately, sometimes occurs and sometimes doesn't. It has been seemingly random when or if it will happen.

Expected behavior A clear and concise description of what you expected to happen.

Screenshots

Desktop (please complete the following information):

OS: Windows
Browser Chrome
Version 69.0.3497.100 (Official Build) (64-bit)

Smartphone (please complete the following information):

Device: Android
OS: 8
Browser Chrome

Additional context Has been occurring on both desktop and mobile. Has been happening fairly regularly for the last couple of days, though I don't know the exact cause without looking at server logs.

@benknoble can you tell anything from looking at the Heroku logs? Point me to a specific line of code or something?

benknoble commented 5 years ago

With the new logging currently in place in the dev branch, I'll be checking the logs. Try it on the dev site (https://mad-eye-moody.herokuapp.com) and let me know when it happens again.

benknoble commented 5 years ago

Oct 12 14:28:48 mad-eye-moody heroku/router:  at=info method=GET path="/" host=mad-eye-moody.herokuapp.com request_id=58faef6e-b55d-4c0c-932f-ccf7b00407c0 fwd="24.106.176.98" dyno=web.1 connect=0ms service=10ms status=200 bytes=2512 protocol=https 
Oct 12 14:28:48 mad-eye-moody heroku/router:  at=info method=GET path="/static/logo.png" host=mad-eye-moody.herokuapp.com request_id=09bda6d2-a2f2-4b25-8eff-ec1810eab162 fwd="24.106.176.98" dyno=web.1 connect=1ms service=8ms status=200 bytes=120182 protocol=https 
Oct 12 14:28:48 mad-eye-moody app/web.1:  [2018-10-12 21:28:47 +0000] [13] [DEBUG] GET / 
Oct 12 14:28:48 mad-eye-moody app/web.1:  10.186.91.179 - - [12/Oct/2018:21:28:47 +0000] "GET / HTTP/1.1" 200 0 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/69.0.3497.100 Safari/537.36" 
Oct 12 14:28:48 mad-eye-moody app/web.1:  [2018-10-12 21:28:47 +0000] [13] [DEBUG] GET /static/main.css 
Oct 12 14:28:48 mad-eye-moody app/web.1:  10.186.91.179 - - [12/Oct/2018:21:28:47 +0000] "GET /static/main.css HTTP/1.1" 200 0 "https://mad-eye-moody.herokuapp.com/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/69.0.3497.100 Safari/537.36" 
Oct 12 14:28:48 mad-eye-moody app/web.1:  [2018-10-12 21:28:47 +0000] [13] [DEBUG] GET /static/logo.png 
Oct 12 14:28:48 mad-eye-moody app/web.1:  10.186.91.179 - - [12/Oct/2018:21:28:47 +0000] "GET /static/logo.png HTTP/1.1" 200 0 "https://mad-eye-moody.herokuapp.com/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/69.0.3497.100 Safari/537.36" 
Oct 12 14:28:48 mad-eye-moody heroku/router:  at=info method=GET path="/static/main.css" host=mad-eye-moody.herokuapp.com request_id=ce447e54-05c6-4849-acb3-5115bfef4f3a fwd="24.106.176.98" dyno=web.1 connect=0ms service=3ms status=200 bytes=706 protocol=https 
Oct 12 14:28:48 mad-eye-moody heroku/router:  at=info method=GET path="/favicon.ico" host=mad-eye-moody.herokuapp.com request_id=6cf318f7-b0dd-4be2-855a-14934d435bd6 fwd="24.106.176.98" dyno=web.1 connect=0ms service=13ms status=404 bytes=386 protocol=https 
Oct 12 14:28:48 mad-eye-moody app/web.1:  [2018-10-12 21:28:48 +0000] [13] [DEBUG] GET /favicon.ico 
Oct 12 14:28:49 mad-eye-moody app/web.1:  10.186.91.179 - - [12/Oct/2018:21:28:48 +0000] "GET /favicon.ico HTTP/1.1" 404 233 "https://mad-eye-moody.herokuapp.com/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/69.0.3497.100 Safari/537.36" 
Oct 12 14:28:49 mad-eye-moody heroku/router:  at=info method=GET path="/create" host=mad-eye-moody.herokuapp.com request_id=2d3ffeff-e66d-494c-8832-b3bb4cc83948 fwd="24.106.176.98" dyno=web.1 connect=0ms service=3ms status=302 bytes=1133 protocol=https 
Oct 12 14:28:49 mad-eye-moody app/web.1:  [2018-10-12 21:28:49 +0000] [13] [DEBUG] GET /create 
Oct 12 14:28:50 mad-eye-moody app/web.1:  10.186.91.179 - - [12/Oct/2018:21:28:49 +0000] "GET /create HTTP/1.1" 302 715 "https://mad-eye-moody.herokuapp.com/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/69.0.3497.100 Safari/537.36" 
Oct 12 14:28:53 mad-eye-moody heroku/router:  at=info method=GET path="/callback?code=AQDqv95MQyyFfx8OyZptie76My_dhlaClkimDWQUpPBmg90W445bKMo3XTmpB94mtFM3Z29uBT-an2q_E_DIFAD01H0fQWzPUV6jiPZt9NmAHLirpeFiykeIKvg54xkIaG0hCRkLaT1zEkvX_KdpQJErv3URx77qEqXfau3t1EorZozN4P1Jypfym2iIwCE8EWcbqW6jHRZhV-zViYizvOjkFJB7F7upNCMo3lU08p8yXhF_o3Nmc15HIDPbmfKNHQjwVdu8fmppPYzLlVUTnPDDHIy8NdGXWxNt8MqYLz5Gheh2HTo" host=mad-eye-moody.herokuapp.com request_id=6f2acc4c-76b8-439d-8678-c38390a7e512 fwd="24.106.176.98" dyno=web.1 connect=0ms service=4ms status=200 bytes=3270 protocol=https 
Oct 12 14:28:53 mad-eye-moody app/web.1:  [2018-10-12 21:28:52 +0000] [13] [DEBUG] GET /callback 
Oct 12 14:28:53 mad-eye-moody app/web.1:  10.186.91.179 - - [12/Oct/2018:21:28:52 +0000] "GET /callback?code=AQDqv95MQyyFfx8OyZptie76My_dhlaClkimDWQUpPBmg90W445bKMo3XTmpB94mtFM3Z29uBT-an2q_E_DIFAD01H0fQWzPUV6jiPZt9NmAHLirpeFiykeIKvg54xkIaG0hCRkLaT1zEkvX_KdpQJErv3URx77qEqXfau3t1EorZozN4P1Jypfym2iIwCE8EWcbqW6jHRZhV-zViYizvOjkFJB7F7upNCMo3lU08p8yXhF_o3Nmc15HIDPbmfKNHQjwVdu8fmppPYzLlVUTnPDDHIy8NdGXWxNt8MqYLz5Gheh2HTo HTTP/1.1" 200 0 "https://accounts.spotify.com/en/login?continue=https:%2F%2Faccounts.spotify.com%2Fen%2Fauthorize%3Fclient_id%3Dee6c71c25f7a4a539d2a51408be8ba97%26response_type%3Dcode%26scope%3Duser-library-read,playlist-read-private,playlist-modify-public%26redirect_uri%3Dhttps:%252F%252Fmad-eye-moody.herokuapp.com%252Fcallback" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/69.0.3497.100 Safari/537.36" 
Oct 12 14:28:53 mad-eye-moody app/web.1:  [2018-10-12 21:28:53 +0000] [12] [DEBUG] GET /static/main.js 
Oct 12 14:28:53 mad-eye-moody app/web.1:  10.186.91.179 - - [12/Oct/2018:21:28:53 +0000] "GET /static/main.js HTTP/1.1" 200 0 "https://mad-eye-moody.herokuapp.com/callback?code=AQDqv95MQyyFfx8OyZptie76My_dhlaClkimDWQUpPBmg90W445bKMo3XTmpB94mtFM3Z29uBT-an2q_E_DIFAD01H0fQWzPUV6jiPZt9NmAHLirpeFiykeIKvg54xkIaG0hCRkLaT1zEkvX_KdpQJErv3URx77qEqXfau3t1EorZozN4P1Jypfym2iIwCE8EWcbqW6jHRZhV-zViYizvOjkFJB7F7upNCMo3lU08p8yXhF_o3Nmc15HIDPbmfKNHQjwVdu8fmppPYzLlVUTnPDDHIy8NdGXWxNt8MqYLz5Gheh2HTo" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/69.0.3497.100 Safari/537.36" 
Oct 12 14:28:53 mad-eye-moody heroku/router:  at=info method=GET path="/static/main.js" host=mad-eye-moody.herokuapp.com request_id=37416a12-2841-43e0-900d-6f0d8e6edd5d fwd="24.106.176.98" dyno=web.1 connect=0ms service=8ms status=200 bytes=2395 protocol=https 
Oct 12 14:29:09 mad-eye-moody app/web.1:  [2018-10-12 21:29:09 +0000] [12] [DEBUG] POST /playlists 
Oct 12 14:29:10 mad-eye-moody heroku/router:  at=info method=POST path="/playlists" host=mad-eye-moody.herokuapp.com request_id=baa9dcaf-395b-46f1-a983-0435e100dc92 fwd="24.106.176.98" dyno=web.1 connect=1ms service=288ms status=500 bytes=456 protocol=https 
Oct 12 14:29:10 mad-eye-moody app/web.1:  [2018-10-12 21:29:09 +0000] [12] [ERROR] Exception on /playlists [POST] 
Oct 12 14:29:10 mad-eye-moody app/web.1:  Traceback (most recent call last): 
Oct 12 14:29:10 mad-eye-moody app/web.1:    File "/app/.heroku/python/lib/python3.6/site-packages/flask/app.py", line 2292, in wsgi_app 
Oct 12 14:29:10 mad-eye-moody app/web.1:      response = self.full_dispatch_request() 
Oct 12 14:29:10 mad-eye-moody app/web.1:    File "/app/.heroku/python/lib/python3.6/site-packages/flask/app.py", line 1815, in full_dispatch_request 
Oct 12 14:29:10 mad-eye-moody app/web.1:      rv = self.handle_user_exception(e) 
Oct 12 14:29:10 mad-eye-moody app/web.1:    File "/app/.heroku/python/lib/python3.6/site-packages/flask/app.py", line 1718, in handle_user_exception 
Oct 12 14:29:10 mad-eye-moody app/web.1:      reraise(exc_type, exc_value, tb) 
Oct 12 14:29:10 mad-eye-moody app/web.1:    File "/app/.heroku/python/lib/python3.6/site-packages/flask/_compat.py", line 35, in reraise 
Oct 12 14:29:10 mad-eye-moody app/web.1:      raise value 
Oct 12 14:29:10 mad-eye-moody app/web.1:    File "/app/.heroku/python/lib/python3.6/site-packages/flask/app.py", line 1813, in full_dispatch_request 
Oct 12 14:29:10 mad-eye-moody app/web.1:      rv = self.dispatch_request() 
Oct 12 14:29:10 mad-eye-moody app/web.1:    File "/app/.heroku/python/lib/python3.6/site-packages/flask/app.py", line 1799, in dispatch_request 
Oct 12 14:29:10 mad-eye-moody app/web.1:      return self.view_functions[rule.endpoint](**req.view_args) 
Oct 12 14:29:10 mad-eye-moody app/web.1:    File "/app/server.py", line 45, in generate_playlist 
Oct 12 14:29:10 mad-eye-moody app/web.1:      token = spotify_service.generate_token(code,scope) 
Oct 12 14:29:10 mad-eye-moody app/web.1:    File "/app/spotify_service.py", line 44, in generate_token 
Oct 12 14:29:10 mad-eye-moody app/web.1:      return sp_oauth.get_access_token(code)['access_token'] 
Oct 12 14:29:10 mad-eye-moody app/web.1:    File "/app/.heroku/python/lib/python3.6/site-packages/spotipy/oauth2.py", line 217, in get_access_token 
Oct 12 14:29:10 mad-eye-moody app/web.1:      raise SpotifyOauthError(response.reason) 
Oct 12 14:29:10 mad-eye-moody app/web.1:  spotipy.oauth2.SpotifyOauthError: Bad Request 
Oct 12 14:29:10 mad-eye-moody app/web.1:  10.186.91.179 - - [12/Oct/2018:21:29:09 +0000] "POST /playlists HTTP/1.1" 500 291 "https://mad-eye-moody.herokuapp.com/callback?code=AQDqv95MQyyFfx8OyZptie76My_dhlaClkimDWQUpPBmg90W445bKMo3XTmpB94mtFM3Z29uBT-an2q_E_DIFAD01H0fQWzPUV6jiPZt9NmAHLirpeFiykeIKvg54xkIaG0hCRkLaT1zEkvX_KdpQJErv3URx77qEqXfau3t1EorZozN4P1Jypfym2iIwCE8EWcbqW6jHRZhV-zViYizvOjkFJB7F7upNCMo3lU08p8yXhF_o3Nmc15HIDPbmfKNHQjwVdu8fmppPYzLlVUTnPDDHIy8NdGXWxNt8MqYLz5Gheh2HTo" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/69.0.3497.100 Safari/537.36"

It appears to be an issue with requesting the access token... I think @richardle798 and I discussed this at some point, but I don't remember

benknoble / mad-eye-moody

Bug on Playlist Creation #18