registration triggers error in log file

[xi]

I just tried to register a new user on my local development system. I got two errors in the UI and the following backend log. Dispite of these issues, I was able to activate my account and log in without issues.

2015-01-05 17:32:57,354 DEBUG [adhocracy_core.resources.principal][MainThread] Sending registration mail to sdf@sdf.sdf for new user named sdf, activation path=/activate/hCkwESvgfzFz7P1qgGvskI0Y
2015-01-05 17:32:57,455 DEBUG [adhocracy_core.websockets.client][MainThread] Sending message to Websocket server: {"resource": "/principals/users/0000003", "event": "created"}
2015-01-05 17:32:57,457 ERROR [txn.140135284180736][MainThread] Error in abort() on manager <repoze.sendmail.delivery.MailDataManager object at 0x7f73be3502e8>
Traceback (most recent call last):
  File "/home/tobib/a3/a3/eggs/transaction-1.4.3-py3.4.egg/transaction/_transaction.py", line 374, in _callAfterCommitHooks
    rm.abort(self)
  File "/home/tobib/a3/a3/eggs/repoze.sendmail-4.2-py3.4.egg/repoze/sendmail/delivery.py", line 119, in abort
    raise ValueError("TPC in progress")
ValueError: TPC in progress
2015-01-05 17:32:57,466 WARNI [adhocracy_core.rest.views][MainThread] Found 2 validation errors in request: <b'{"content_type":"adhocracy_core.resources.principal.IUser","data":{"adhocracy_core.sheets.principal.IUserBasic":{"name":"sdf","email":"sdf@sdf.sdf"},"adhocracy_core.sheets.principal.IPasswordAuthentication":{"password":"sdfsdf"}}}'>
2015-01-05 17:32:57,466 WARNI [adhocracy_core.rest.views][MainThread]   {'description': 'The user login name is not unique', 'name': 'data.adhocracy_core.sheets.principal.IUserBasic.name', 'location': 'body'}
2015-01-05 17:32:57,467 WARNI [adhocracy_core.rest.views][MainThread]   {'description': 'The user login email is not unique', 'name': 'data.adhocracy_core.sheets.principal.IUserBasic.email', 'location': 'body'}

[ChristianSi]

Googling "TPC in progress" led me to this StackOverflow page, which says:

This is a known issue. It can be worked around in the meantime by reverting to repoze.sendmail 4.1 (from 4.2)

So I guess we should pin repoze.sendmail to 4.1 for the time being.

[nidico]

Pinning repoze.sendmail==4.1 as proposed in repoze/repoze.sendmail#31 leads to another backend error (and also still works):

2015-01-06 14:11:24,868 ERROR [txn.140452977841920][MainThread] Error in abort() on manager <repoze.sendmail.delivery.MailDataManager object at 0x7fbdadda71d0>
Traceback (most recent call last):
  File "/home/nico/src/a3/eggs/transaction-1.4.3-py3.4.egg/transaction/_transaction.py", line 374, in _callAfterCommitHooks
    rm.abort(self)
  File "/home/nico/src/a3/eggs/repoze.sendmail-4.1-py3.4.egg/repoze/sendmail/delivery.py", line 48, in abort
    self.onAbort()
  File "/home/nico/src/a3/eggs/repoze.sendmail-4.1-py3.4.egg/repoze/sendmail/maildir.py", line 133, in abort
    raise RuntimeError('Cannot abort--already committed.')
RuntimeError: Cannot abort--already committed.

Not sure if this is any better, so I wouldn't do that now.

[ChristianSi]

As far as I can see, nothing is really broken, it's just a strange error message in the log file. What seems to happen is:

• Transaction.commit is called (in adhocracy/a3/eggs/transaction-1.4.3-py3.4.egg/transaction/_transaction.py)
• At the end of this method, self._callAfterCommitHooks(status=True) is called
• Now the code gets a bit strange/confusing: even though the transaction was successful, _callAfterCommitHooks calls abort on all resources in self._resources (line 374), with the comment: "The transaction is already committed. It must not have further effects after the commit."
• One of the resources listed there is repoze.sendmail.delivery.MailDataManager. Its abort method then raises ValueError("TPC in progress") (adhocracy/a3/eggs/repoze.sendmail-4.2-py3.4.egg/repoze/sendmail/delivery.py, line 119) which is catched and logged by _callAfterCommitHooks.
• In repoze.sendmail 4.1, the ValueError is not thrown, but the abort method calls self.onAbort() which then raises a RuntimeError('Cannot abort--already committed.')

So what seems to happen is the following:

• transaction thinks it's fine to call abort on resources after a successful commit to make sure they won't commit anything else.
• repoze.sendmail thinks that calling abort after commit is an error.
• repoze.sendmail 4.2 confuses things further by throwing the "TPC in progress" error, which is a "known problem" (see above).

Right now I don't see how we can clean up this mess on our side. We could just live with the error in the logs -- it seems to be harmless, but that wouldn't be a nice solution. @joka do you have a better idea?

[xi]

The more important aspect for me are the last two lines in the log I posted in the OP: I get "The user login email is not unique" and "The user login name is not unique" which is also shown in the frontend.

[ChristianSi]

@xi I never get those, so you would have to tell us how to reproduce.

[xi]

I get these errors consitently when I try to register on my local installation. No clue why. Should we close this and reopen when someone else can reproduce?

[ChristianSi]

I don't want to close this since the "TPC in progress" error in the logs is ugly in any case. @joka maybe you have an idea?