Cannot register a new user : Internal Server Error

[vj-codes]

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]

@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

[isabelcosta]

I tried it now using this data:

POST /register

{
  "name": "Lola Iris",
  "username": "lolairis",
  "password": "12345678",
  "email": "wixik21324@brayy.com",
  "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': 'wixik21324@brayy.com', '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]

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

[isabelcosta]

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

[epicadk]

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': 'wixik21324@brayy.com', '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]

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

[epicadk]

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]

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]

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': 'woyeca5467@flmmo.com', '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

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]

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.