Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Cannot register a new user : Internal Server Error #1109

Open
vj-codes opened this issue May 19, 2021 · 15 comments
Open

Cannot register a new user : Internal Server Error #1109

vj-codes opened this issue May 19, 2021 · 15 comments
Labels
Type: Bug Bug or Bug fixes. Type: Maintenance Repository maintenance. Type: Question Further information is requested.

Comments

@vj-codes
Copy link
Member

Describe the bug

When I try to register a new user via the app or deployed Heroku link , Internal Server Error is found

To Reproduce

Steps to reproduce the behavior:

  1. Go to 'https://mentorship-backend-temp.herokuapp.com/register'
  2. Enter required fields
  3. See the error

Expected behavior

The new user should be registered successfully

@vj-codes
Copy link
Member Author

vj-codes commented May 19, 2021

@isabelcosta I believe this has something to do with #1101 or previous merged commits , I think only you have access to fix it 👀
Original issue posted on android

@vj-codes vj-codes added Type: Bug Bug or Bug fixes. Type: Maintenance Repository maintenance. Type: Question Further information is requested. labels May 19, 2021
@isabelcosta
Copy link
Member

I tried it now using this data:

POST /register

{
  "name": "Lola Iris",
  "username": "lolairis",
  "password": "12345678",
  "email": "[email protected]",
  "terms_and_conditions_checked": true,
  "need_mentoring": true,
  "available_to_mentor": true
}

And I inspected and I got this error from Heroku console

Click to expand!
2021-05-24T18:39:44.676923+00:00 app[web.1]: [2021-05-24 18:39:44 +0000] [10] [ERROR] Error handling request /register
2021-05-24T18:39:44.676941+00:00 app[web.1]: Traceback (most recent call last):
2021-05-24T18:39:44.676942+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1771, in _execute_context
2021-05-24T18:39:44.676942+00:00 app[web.1]:     cursor, statement, parameters, context
2021-05-24T18:39:44.676942+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/sqlalchemy/engine/default.py", line 717, in do_execute
2021-05-24T18:39:44.676943+00:00 app[web.1]:     cursor.execute(statement, parameters)
2021-05-24T18:39:44.676943+00:00 app[web.1]: psycopg2.errors.StringDataRightTruncation: value too long for type character varying(100)
2021-05-24T18:39:44.676944+00:00 app[web.1]: 
2021-05-24T18:39:44.676944+00:00 app[web.1]: 
2021-05-24T18:39:44.676944+00:00 app[web.1]: The above exception was the direct cause of the following exception:
2021-05-24T18:39:44.676944+00:00 app[web.1]: 
2021-05-24T18:39:44.676945+00:00 app[web.1]: Traceback (most recent call last):
2021-05-24T18:39:44.676945+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/gunicorn/workers/sync.py", line 134, in handle
2021-05-24T18:39:44.676945+00:00 app[web.1]:     self.handle_request(listener, req, client, addr)
2021-05-24T18:39:44.676946+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/gunicorn/workers/sync.py", line 175, in handle_request
2021-05-24T18:39:44.676946+00:00 app[web.1]:     respiter = self.wsgi(environ, resp.start_response)
2021-05-24T18:39:44.676946+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/flask/app.py", line 2309, in __call__
2021-05-24T18:39:44.676946+00:00 app[web.1]:     return self.wsgi_app(environ, start_response)
2021-05-24T18:39:44.676946+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/flask/app.py", line 2295, in wsgi_app
2021-05-24T18:39:44.676947+00:00 app[web.1]:     response = self.handle_exception(e)
2021-05-24T18:39:44.676947+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/flask_restx/api.py", line 638, in error_router
2021-05-24T18:39:44.676947+00:00 app[web.1]:     return original_handler(f)
2021-05-24T18:39:44.676947+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/flask/app.py", line 1741, in handle_exception
2021-05-24T18:39:44.676948+00:00 app[web.1]:     reraise(exc_type, exc_value, tb)
2021-05-24T18:39:44.676948+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/flask/_compat.py", line 35, in reraise
2021-05-24T18:39:44.676948+00:00 app[web.1]:     raise value
2021-05-24T18:39:44.676948+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/flask_restx/api.py", line 636, in error_router
2021-05-24T18:39:44.676949+00:00 app[web.1]:     return self.handle_error(e)
2021-05-24T18:39:44.676949+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/flask/app.py", line 2292, in wsgi_app
2021-05-24T18:39:44.676949+00:00 app[web.1]:     response = self.full_dispatch_request()
2021-05-24T18:39:44.676949+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/flask/app.py", line 1815, in full_dispatch_request
2021-05-24T18:39:44.676949+00:00 app[web.1]:     rv = self.handle_user_exception(e)
2021-05-24T18:39:44.676950+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/flask_restx/api.py", line 638, in error_router
2021-05-24T18:39:44.676950+00:00 app[web.1]:     return original_handler(f)
2021-05-24T18:39:44.676950+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/flask/app.py", line 1718, in handle_user_exception
2021-05-24T18:39:44.676952+00:00 app[web.1]:     reraise(exc_type, exc_value, tb)
2021-05-24T18:39:44.676952+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/flask/_compat.py", line 35, in reraise
2021-05-24T18:39:44.676952+00:00 app[web.1]:     raise value
2021-05-24T18:39:44.676952+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/flask_restx/api.py", line 636, in error_router
2021-05-24T18:39:44.676953+00:00 app[web.1]:     return self.handle_error(e)
2021-05-24T18:39:44.676953+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/flask/app.py", line 1813, in full_dispatch_request
2021-05-24T18:39:44.676953+00:00 app[web.1]:     rv = self.dispatch_request()
2021-05-24T18:39:44.676957+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/flask/app.py", line 1799, in dispatch_request
2021-05-24T18:39:44.676957+00:00 app[web.1]:     return self.view_functions[rule.endpoint](**req.view_args)
2021-05-24T18:39:44.676957+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/flask_restx/api.py", line 375, in wrapper
2021-05-24T18:39:44.676957+00:00 app[web.1]:     resp = resource(*args, **kwargs)
2021-05-24T18:39:44.676958+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/flask/views.py", line 88, in view
2021-05-24T18:39:44.676958+00:00 app[web.1]:     return self.dispatch_request(*args, **kwargs)
2021-05-24T18:39:44.676958+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/flask_restx/resource.py", line 44, in dispatch_request
2021-05-24T18:39:44.676958+00:00 app[web.1]:     resp = meth(*args, **kwargs)
2021-05-24T18:39:44.676958+00:00 app[web.1]:   File "/app/app/api/resources/user.py", line 333, in post
2021-05-24T18:39:44.676959+00:00 app[web.1]:     result = DAO.create_user(data)
2021-05-24T18:39:44.676959+00:00 app[web.1]:   File "/app/app/api/dao/user.py", line 69, in create_user
2021-05-24T18:39:44.676959+00:00 app[web.1]:     user.save_to_db()
2021-05-24T18:39:44.676959+00:00 app[web.1]:   File "/app/app/database/models/user.py", line 152, in save_to_db
2021-05-24T18:39:44.676959+00:00 app[web.1]:     db.session.commit()
2021-05-24T18:39:44.676960+00:00 app[web.1]:   File "<string>", line 2, in commit
2021-05-24T18:39:44.676960+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/sqlalchemy/orm/session.py", line 1428, in commit
2021-05-24T18:39:44.676960+00:00 app[web.1]:     self._transaction.commit(_to_root=self.future)
2021-05-24T18:39:44.676960+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/sqlalchemy/orm/session.py", line 829, in commit
2021-05-24T18:39:44.676960+00:00 app[web.1]:     self._prepare_impl()
2021-05-24T18:39:44.676961+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/sqlalchemy/orm/session.py", line 808, in _prepare_impl
2021-05-24T18:39:44.676961+00:00 app[web.1]:     self.session.flush()
2021-05-24T18:39:44.676961+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/sqlalchemy/orm/session.py", line 3262, in flush
2021-05-24T18:39:44.676966+00:00 app[web.1]:     self._flush(objects)
2021-05-24T18:39:44.676966+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/sqlalchemy/orm/session.py", line 3402, in _flush
2021-05-24T18:39:44.676966+00:00 app[web.1]:     transaction.rollback(_capture_exception=True)
2021-05-24T18:39:44.676967+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/sqlalchemy/util/langhelpers.py", line 72, in __exit__
2021-05-24T18:39:44.676967+00:00 app[web.1]:     with_traceback=exc_tb,
2021-05-24T18:39:44.676967+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 211, in raise_
2021-05-24T18:39:44.676967+00:00 app[web.1]:     raise exception
2021-05-24T18:39:44.676967+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/sqlalchemy/orm/session.py", line 3362, in _flush
2021-05-24T18:39:44.676967+00:00 app[web.1]:     flush_context.execute()
2021-05-24T18:39:44.676968+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/sqlalchemy/orm/unitofwork.py", line 455, in execute
2021-05-24T18:39:44.676968+00:00 app[web.1]:     rec.execute(self)
2021-05-24T18:39:44.676968+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/sqlalchemy/orm/unitofwork.py", line 632, in execute
2021-05-24T18:39:44.676968+00:00 app[web.1]:     uow,
2021-05-24T18:39:44.676969+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/sqlalchemy/orm/persistence.py", line 247, in save_obj
2021-05-24T18:39:44.676969+00:00 app[web.1]:     insert,
2021-05-24T18:39:44.676969+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/sqlalchemy/orm/persistence.py", line 1222, in _emit_insert_statements
2021-05-24T18:39:44.676969+00:00 app[web.1]:     execution_options=execution_options,
2021-05-24T18:39:44.676969+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1582, in _execute_20
2021-05-24T18:39:44.676970+00:00 app[web.1]:     return meth(self, args_10style, kwargs_10style, execution_options)
2021-05-24T18:39:44.676970+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/sqlalchemy/sql/elements.py", line 330, in _execute_on_connection
2021-05-24T18:39:44.676970+00:00 app[web.1]:     self, multiparams, params, execution_options
2021-05-24T18:39:44.676970+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1461, in _execute_clauseelement
2021-05-24T18:39:44.676971+00:00 app[web.1]:     cache_hit=cache_hit,
2021-05-24T18:39:44.676971+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1814, in _execute_context
2021-05-24T18:39:44.676971+00:00 app[web.1]:     e, statement, parameters, cursor, context
2021-05-24T18:39:44.676971+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1995, in _handle_dbapi_exception
2021-05-24T18:39:44.676972+00:00 app[web.1]:     sqlalchemy_exception, with_traceback=exc_info[2], from_=e
2021-05-24T18:39:44.676972+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 211, in raise_
2021-05-24T18:39:44.676972+00:00 app[web.1]:     raise exception
2021-05-24T18:39:44.676973+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1771, in _execute_context
2021-05-24T18:39:44.676973+00:00 app[web.1]:     cursor, statement, parameters, context
2021-05-24T18:39:44.676973+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/sqlalchemy/engine/default.py", line 717, in do_execute
2021-05-24T18:39:44.676973+00:00 app[web.1]:     cursor.execute(statement, parameters)
2021-05-24T18:39:44.676974+00:00 app[web.1]: sqlalchemy.exc.DataError: (psycopg2.errors.StringDataRightTruncation) value too long for type character varying(100)
2021-05-24T18:39:44.676974+00:00 app[web.1]: 
2021-05-24T18:39:44.676974+00:00 app[web.1]: [SQL: INSERT INTO users (name, username, email, password_hash, registration_date, terms_and_conditions_checked, is_admin, is_email_verified, email_verification_date, current_mentorship_role, membership_status, bio, location, occupation, organization, slack_username, social_media_links, skills, interests, resume_url, photo_url, need_mentoring, available_to_mentor) VALUES (%(name)s, %(username)s, %(email)s, %(password_hash)s, %(registration_date)s, %(terms_and_conditions_checked)s, %(is_admin)s, %(is_email_verified)s, %(email_verification_date)s, %(current_mentorship_role)s, %(membership_status)s, %(bio)s, %(location)s, %(occupation)s, %(organization)s, %(slack_username)s, %(social_media_links)s, %(skills)s, %(interests)s, %(resume_url)s, %(photo_url)s, %(need_mentoring)s, %(available_to_mentor)s) RETURNING users.id]
2021-05-24T18:39:44.676976+00:00 app[web.1]: [parameters: {'name': 'Lola Iris', 'username': 'lolairis', 'email': '[email protected]', 'password_hash': 'pbkdf2:sha256:260000$BvOxJpco73bu1twS$0e4cff3d19bd62da76531134dd7181a936fa5f8ca7285252e0781a55170b046d', 'registration_date': 1621881584.6659381, 'terms_and_conditions_checked': True, 'is_admin': False, 'is_email_verified': False, 'email_verification_date': None, 'current_mentorship_role': None, 'membership_status': None, 'bio': None, 'location': None, 'occupation': None, 'organization': None, 'slack_username': None, 'social_media_links': None, 'skills': None, 'interests': None, 'resume_url': None, 'photo_url': None, 'need_mentoring': True, 'available_to_mentor': True}]
2021-05-24T18:39:44.676976+00:00 app[web.1]: (Background on this error at: http://sqlalche.me/e/14/9h9h)
2021-05-24T18:39:44.677199+00:00 app[web.1]: 10.1.17.47 - - [24/May/2021:18:39:44 +0000] "POST /register HTTP/1.1" 500 0 "-" "-"

cc @anitab-org/mentorship-maintainers I haven't had tome to look into this yet, but I think we can try to figure out from this log ^^

@devkapilbansal
Copy link
Member

I remember opening a similar issue but closed it as I wasn't able to retrace it

@isabelcosta
Copy link
Member

Also, just to rule this out, I checked and we have not yet hit the limit of users on our DB.

current database size is 1mb

@epicadk
Copy link
Member

epicadk commented May 24, 2021

sqlalchemy.exc.DataError: (psycopg2.errors.StringDataRightTruncation) value too long for type character varying(100)

This is the error.

[parameters: {'name': 'Lola Iris', 'username': 'lolairis', 'email': '[email protected]', 'password_hash': 'pbkdf2:sha256:260000$BvOxJpco73bu1twS$0e4cff3d19bd62da76531134dd7181a936fa5f8ca7285252e0781a55170b046d', 'registration_date': 1621881584.6659381, 'terms_and_conditions_checked': True, 'is_admin': False, 'is_email_verified': False, 'email_verification_date': None, 'current_mentorship_role': None, 'membership_status': None, 'bio': None, 'location': None, 'occupation': None, 'organization': None, 'slack_username': None, 'social_media_links': None, 'skills': None, 'interests': None, 'resume_url': None, 'photo_url': None, 'need_mentoring': True, 'available_to_mentor': True}]

This is the statement. I think it's because the hash is overflowing the varchar limit.

@isabelcosta
Copy link
Member

oh wow @epicadk so, it's a problem with the length set for the password field?

@epicadk
Copy link
Member

epicadk commented May 24, 2021

oh wow @epicadk so, it's a problem with the length set for the password field?

Yep, atleast that's what I can infer from the logs.

@devkapilbansal
Copy link
Member

I remember opening a similar issue but closed it as I wasn't able to retrace it

@isabelcosta @epicadk here it is #931 but it is different from this one 🤔

@isabelcosta
Copy link
Member

We tried again and can confirm the issue is still existing, and we have to adjust the limit of the password_hash. There should not be a limit defined on the SQL Alchemy.

So the problem here is that we have a limit for the password size, but we can't control the size of the hashing form of the password, so we are limiting it to 100 characters when often this hashing surpasses that value.

(...)
2021-07-24T13:20:40.552636+00:00 app[web.1]:     cursor, statement, parameters, context
2021-07-24T13:20:40.552636+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.6/site-packages/sqlalchemy/engine/default.py", line 717, in do_execute
2021-07-24T13:20:40.552637+00:00 app[web.1]:     cursor.execute(statement, parameters)
2021-07-24T13:20:40.552637+00:00 app[web.1]: sqlalchemy.exc.DataError: (psycopg2.errors.StringDataRightTruncation) value too long for type character varying(100)
2021-07-24T13:20:40.552637+00:00 app[web.1]: 
2021-07-24T13:20:40.552638+00:00 app[web.1]: [SQL: INSERT INTO users (name, username, email, password_hash, registration_date, terms_and_conditions_checked, is_admin, is_email_verified, email_verification_date, current_mentorship_role, membership_status, bio, location, occupation, organization, slack_username, social_media_links, skills, interests, resume_url, photo_url, need_mentoring, available_to_mentor) VALUES (%(name)s, %(username)s, %(email)s, %(password_hash)s, %(registration_date)s, %(terms_and_conditions_checked)s, %(is_admin)s, %(is_email_verified)s, %(email_verification_date)s, %(current_mentorship_role)s, %(membership_status)s, %(bio)s, %(location)s, %(occupation)s, %(organization)s, %(slack_username)s, %(social_media_links)s, %(skills)s, %(interests)s, %(resume_url)s, %(photo_url)s, %(need_mentoring)s, %(available_to_mentor)s) RETURNING users.id]
2021-07-24T13:20:40.552639+00:00 app[web.1]: [parameters: {'name': 'Filipa', 'username': 'filipa4', 'email': '[email protected]', 'password_hash': 'pbkdf2:sha256:260000$EVJrmk4EkMf9RSJ8$6fb8e13dbfb1f49a16caf89520986570f228597d0c7b4c49e89c011c05acdaf5', 'registration_date': 1627132840.5392268, 'terms_and_conditions_checked': True, 'is_admin': False, 'is_email_verified': False, 'email_verification_date': None, 'current_mentorship_role': None, 'membership_status': None, 'bio': None, 'location': None, 'occupation': None, 'organization': None, 'slack_username': None, 'social_media_links': None, 'skills': None, 'interests': None, 'resume_url': None, 'photo_url': None, 'need_mentoring': True, 'available_to_mentor': True}]
2021-07-24T13:20:40.552640+00:00 app[web.1]: (Background on this error at: https://sqlalche.me/e/14/9h9h)
2021-07-24T13:20:40.552823+00:00 app[web.1]: 10.1.85.122 - - [24/Jul/2021:13:20:40 +0000] "POST /register HTTP/1.1" 500 0 "-" "-"
2021-07-24T13:20:40.554587+00:00 heroku[router]: at=info method=POST path="/register" host=mentorship-backend-temp.herokuapp.com request_id=24aeadeb-d87c-4dbf-9743-af39b040da17 fwd="81.151.230.108" dyno=web.1 connect=0ms service=215ms status=500 bytes=244 protocol=https

print from swagger with the error
print from swagger with the error

Next steps:

  • Create an issue to remove the password_hash limit or define a bigger one. If the first option is possible, would be better.

cc tested this w/ @vj-codes @devkapilbansal @ravi5175

@epicadk
Copy link
Member

epicadk commented Jul 25, 2021

We tried again and can confirm the issue is still existing, and we have to adjust the limit of the password_hash. There should not be a limit defined on the SQL Alchemy.

I disagree. The length of the output of a hash function is constant.

https://en.wikipedia.org/wiki/Cryptographic_hash_function#Properties
First line under properties.

@isabelcosta
Copy link
Member

@epicadk good point 👍🏾 I had that brief thought, but then seeing that the error is about the limit of the property, I saw removing/extending the limit as a potential solution.
What is the limit in this case, what would you suggest we do instead?

@epicadk
Copy link
Member

epicadk commented Jul 26, 2021

@epicadk good point 👍🏾 I had that brief thought, but then seeing that the error is about the limit of the property, I saw removing/extending the limit as a potential solution.
What is the limit in this case, what would you suggest we do instead?

Yup extending seems like the way to go. I think the library we are using uses SHA256 by default.

@isabelcosta
Copy link
Member

@epicadk that seems to be what I described in the follow-up issue. Is there anything I should correct there to not misguide contributors?

@epicadk
Copy link
Member

epicadk commented Jul 29, 2021

@epicadk that seems to be what I described in the follow-up issue. Is there anything I should correct there to not misguide contributors?

Well the title is remove the limit, so that is a bit misleading. We should extend the limit instead so maybe you could update the title of the pr.

@mariejp
Copy link

mariejp commented Apr 8, 2022

Hello!
Is this issue still available? I would like to work on it!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Type: Bug Bug or Bug fixes. Type: Maintenance Repository maintenance. Type: Question Further information is requested.
Projects
None yet
Development

No branches or pull requests

5 participants