In message <20111017081202.GB22486@runtux.com>,
Ralf Schlatterbeck writes:

>On Sat, Oct 15, 2011 at 06:49:41PM -0400, John P. Rouillard wrote:
>> Hi all:
>> 
>> With the work going on with pgp signing of email messages, I thought
>> this may be a good time to bring up the idea of attaching an origin to
>> transactions that change the database.
>
>Nice. Can you put this idea into the issue tracker at
>http://issues.roundup-tracker.org/
>(as an "rfe" which translates to "request for enhancement" I think :-)
>
>I've had some usecases where it would be nice to find out the origin
>of a request from a detector... You're adding some interesting usecases.

The original use case was for secure tickets where only certain people
are allowed to view them. For my tutorial example, I am using the nosy
list as the access control list. If I allow email updates to tickets,
it is trivial to forge a from address and change the nosy list
(Subject: ... [nosy=+badguy]). So I have to add a caveat that you have
to disable email changes (or filter the emails in some way before they
hit roundup) in order for the security to be less soft.

Here is the original message as well.

============
Hi all:

With the work going on with pgp signing of email messages, I thought
this may be a good time to bring up the idea of attaching an origin to
transactions that change the database.

E.G. while you may want to allow new messages to be added to an issue
via email, changing the assignedto person may be done only via the web
or openpgpg signed emails.

I am specifically thinking of supplying the info to auditors so they
can make useful decisions on allowing/denying a database change, but
it may be useful for reactors as well.

Maybe adding a db.requestmode() similar to db.getuid(), or maybe a
generalized version of the request object available to the web
interface could be created. Then it could be set by the front end to:

   web
   xmlrpc
   email
   openpgp-email (for a validated signed email)
   cli
   program-<prog name>

via some function call and it would default to none if the program
didn't set its identifier. Then in the auditor/reactor you could use

   if not db.requestmode() in ['web', 'xmlrpc', 'openpgp-email', 'cli']:
        raise Reject, "Change did not arrive via autheticated channel"
====================

-- rouilj

Interesting, for a customer I have a similar setup: we have a
"confidential" flag (Boolean) that makes the issue readable only for
people on the nosy list if set.
I have made an additional check-method that allows visibility of
messages only if the issue to which the message is connected is visible
for the user -- this can be done with permission methods (in our setup
the most confidential information is in messages, so a user could
shoulder-surf or otherwise find out the message number to get access to
confidential information if messages were not protected by permissions).
I've also made an auditor that tests if someone attaches an already
existing message to an issue (e.g. via XMLRPC or a crafted web-request)
to get read-access to the message. But I failed to notice how easy it
would be to forge emails ... 

so it looks like there are several use-cases for your proposal.

Ralf Schlatterbeck in msg4450 said:

> I have made an additional check-method that allows
> visibility of messages only if the issue to which the
> message is connected is visible for the user

Yup did the same for my messages class. I left doing the
same for the file class as an exercise for the students 8-).

> I've also made an auditor that tests if someone attaches
> an already existing message to an issue (e.g. via XMLRPC
> or a crafted web-request) to get read-access to the
> message.

In my case I only allow adding a message to the issue's
messages multilink to be done by the owner of the message
being added. So if the user didn't originate the message,
s/he can't add it to any other issue.

> But I failed to notice how easy it would be to forge
> emails ...

Yup. It's a pretty big hole unfortunately. It can be mitigated
somewhat by forcing all changes to be sent to the nosy list (otherwise
a message with no body will result in an invisible change except in
the history of the issue). Hopefully with all changes being sent to
the nosy list, somebody will notice the nosy list change. But that is
more a detection method in absence of being able to limit the change
in the first place.

On Tue, Oct 18, 2011 at 08:29:06PM +0000, John Rouillard wrote:
> > I've also made an auditor that tests if someone attaches
> > an already existing message to an issue (e.g. via XMLRPC
> > or a crafted web-request) to get read-access to the
> > message.
> 
> In my case I only allow adding a message to the issue's
> messages multilink to be done by the owner of the message
> being added. So if the user didn't originate the message,
> s/he can't add it to any other issue.

Same here, seems we have invented the same wheel independently :-)

> > But I failed to notice how easy it would be to forge
> > emails ...
> 
> Yup. It's a pretty big hole unfortunately. It can be mitigated
> somewhat by forcing all changes to be sent to the nosy list (otherwise
> a message with no body will result in an invisible change except in
> the history of the issue).

Yes we have that and since this is a corporate setting where most people
working on an issue know each other it would be noticed with high
probability.

Ralf
-- 
Dr. Ralf Schlatterbeck                  Tel:   +43/2243/26465-16
Open Source Consulting                  www:   http://www.runtux.com
Reichergasse 131, A-3411 Weidling       email: office@runtux.com
osAlliance member                       email: rsc@osalliance.com

The following patch changes roundup 1.4.19 to provide a new db.txSource
parameter that has one of 4 values currently:

  unset - reported when using a script/roundup-admin
  cgi - reported when using any web based technique
  email - reported when using any email based technique
  email/pgp - reported when email based technique uses pgp signed emails
 
The detector (to be attached) can be used to test the code.

Currently it has been tested with standard email (not pgp signed)
and the stand alone web server (using the demo.py mechanism).

As it stands I claim it can be rolled into a release with a note to
see this ticket for it's current testing status. It doesn't change
any current functionality so it should be safe for deployment.

It should be tested:
   to report email/pgp for pgp signed emails
   against postgresql or mysql database with multiple overlapping
      transactions via different methods to verify that each issue
      maintains the same txSource through the detectors.

The attached file can be dropped into a detectors directory
and the server restarted.

To test with it, start multiple updates via email, web and
email/pgp and the detector will put out data like:

Example output when the web interface changes item 3 and the email
(non pgp) interface changes item 4:

txSourceCheckAudit(3) pre db.txSource: cgi
txSourceCheckAudit(4) pre db.txSource: email
txSourceCheckAudit(3) post db.txSource: cgi
txSourceCheckAudit(4) post db.txSource: email
txSourceCheckReact(4) pre db.txSource: email
txSourceCheckReact(4) post db.txSource: email
txSourceCheckReact(3) pre db.txSource: cgi
txSourceCheckReact(3) post db.txSource: cgi

Note that the calls are interleaved, but the proper
txSource is associated with the same ticket.

Seems we need someone to at least peek a look
and to the remaning tests.

Ralf, as you have implemented something similiar, what is your take on
it?

John, maybe you can ask on the list if someone is interested to do the
remaining tests or a review.

In message
<1334563804.75.0.915563952183.issue2550731@psf.upfronthosting.co.za> ,
Bernhard Reiter writes:

>Bernhard Reiter <bernhard@intevation.de> added the comment:
>John, maybe you can ask on the list if someone is interested to do the
>remaining tests or a review.

Will do.

What's the status of this?

This feature would be useful for two issues reported in the Python
meta-tracker:
http://psf.upfronthosting.co.za/roundup/meta/issue295
http://psf.upfronthosting.co.za/roundup/meta/issue400

On Tue, May 22, 2012 at 01:42:20AM +0000, Ezio Melotti wrote:
> 
> What's the status of this?
> 
> This feature would be useful for two issues reported in the Python
> meta-tracker:
> http://psf.upfronthosting.co.za/roundup/meta/issue295
> http://psf.upfronthosting.co.za/roundup/meta/issue400

Interesting use-cases.

I had given John commit access to commit this issue. I'd like to see a
test for it, too. Maybe you two want to collaborate on getting this in
-- including a test? I'd help with questions.

Ralf

I also thought it should have gone in, but I did not check before the
release.

We have an open issue with this against postgres (and probably mysql)

See:
 
http://old.nabble.com/Wierd-bug-in-roundup-1.4.20-with-postgres-back-end-td33958179.html

We have to code a test as well:

 
http://old.nabble.com/Need-testing-help-for-issue2550731-allow-detectors-to-reject-insecure-changes-td33701817.html

the last email trail included a request to change the property from
txSource to tx_source before comitting.

Hi John,
I've poked around in the code and I'm attaching a hg export
  issue2550731-20130102ber.patch
it is NOT TESTED (as I ran out of time)

a) I've changed the states and the variable name
b) From browsing the code it seems that the email-sign-openpgp place
may not be working correctly in all cases. Emails could be only
encrypted or encrypted and signed. I'm not sure of reaching this code
point always means they have been sucessfully verified.
c) hg export applies to 4717:9dc50be521ee

Was the fact that you were using a remote postresgl database
important for the reproduction of your unwanted behaviour?


Maybe it helps!
Bernhard

In message <1357163025.25.0.816891681034.issue2550731@psf.upfronthosting.co.za>
 <1357163025.25.0.816891681034.issue2550731@psf.upfronthosting.co.za>,
Bernhard Reiter writes:
>Bernhard Reiter added the comment:
>I've poked around in the code and I'm attaching a hg export
>  issue2550731-20130102ber.patch
>it is NOT TESTED (as I ran out of time)
>a) I've changed the states and the variable name
>b) From browsing the code it seems that the email-sign-openpgp place
>   may not be working correctly in all cases. Emails could be only
>   encrypted or encrypted and signed. I'm not sure of reaching this code
>   point always means they have been sucessfully verified.
>c) hg export applies to 4717:9dc50be521ee
>
>Was the fact that you were using a remote postresgl database
>important for the reproduction of your unwanted behaviour?

Yes it was.

When I get a chance to look at the patch, I'll comment back here.

One idea I also had was to create a testing tracker with appropriate
fields (e.g. arrivalMethod fields in the msgs and issue) that I could
change from the auditor. This would be required for unit testing
purposes anyway.

| >Was the fact that you were using a remote postresgl database
| >important for the reproduction of your unwanted behaviour?
| Yes it was.

Hmm, so a local postgresql database would work? This would pose
the question what the difference between a local and a remote
postresgql database is. Some timelag in the connection? Probably not.
Some driving code using the connection in different - say blocking -
manner?

Could you attach or send me all the infos or files that you have that
make me or someone else be able to reproduce your issue as easily
as possible? Send it to me personally, if you cannot attach it here.
I may be willing to look into it, and the faster I can get to the point
to reproduce the behaviour you having difficulties with, the higher the
change that I can help. :)

Best,
Bernhard

In message <1357207431.43.0.96131456964.issue2550731@psf.upfronthosting.co.za> 
<1357207431.43.0.96131456964.issue2550731@psf.upfronthosting.co.za>,
Bernhard Reiter writes:
>Bernhard Reiter added the comment:
>
>| >Was the fact that you were using a remote postresgl database
>| >important for the reproduction of your unwanted behaviour?
>| Yes it was.
>
>Hmm, so a local postgresql database would work? This would pose
>the question what the difference between a local and a remote
>postresgql database is. Some timelag in the connection? Probably not.
>Some driving code using the connection in different - say blocking -
>manner?

Ah, I am not sure about local/vs remote database. I did not see the
issue with the local file databases dbm/sqlite. I was told at the time
that the big difference was serial vs parallel access to the database.

>Could you attach or send me all the infos or files that you have that
>make me or someone else be able to reproduce your issue as easily
>as possible? Send it to me personally, if you cannot attach it here.
>I may be willing to look into it, and the faster I can get to the point
>to reproduce the behaviour you having difficulties with, the higher the
>change that I can help. :)

The patch file for roundup is on the the issue already and the
additional detector change and the problem I see is described at:

  http://sourceforge.net/mailarchive/message.php?msg_id=29359236

I'll try to get that integrated into a working detector (auditor
really) this weekend, but that should give you enough info to set up
your own. I am not sure if it is a problem with journaling or the
flow through the detectors.

I was talking with somebody at the LISA conference a few weeks ago and
mentioned that the journaling was wrong and he said that it may be a
known bug as he saw something similar but I never got any additional
info.

John,
as for the postgresl database, you were writing "on a remote server"
so I wasn't sure if there is a difference between local and a remotely running
PostgreSQL connection. Yes, PostgreSQL will have parallel access
in both cases.

I just wanted to make sure that I can easily reproduce your issue, which is
the next step in analysing it further.

Best,
Bernhard

Hi Bernhard:

In message <1357326771.66.0.913231534344.issue2550731@psf.upfronthosting.co.za>
 <1357326771.66.0.913231534344.issue2550731@psf.upfronthosting.co.za>,
Bernhard Reiter writes:
>Bernhard Reiter added the comment:
>as for the postgresl database, you were writing "on a remote server"
>so I wasn't sure if there is a difference between local and a remotely runni
>ng
>PostgreSQL connection. Yes, PostgreSQL will have parallel access
>in both cases.
>
>I just wanted to make sure that I can easily reproduce your issue, which is
>the next step in analysing it further.

I think it's the parallel nature of the database access and not the
"remoteness" of the database that's the issue here.

I expect local network/socket access to a postgres database would
cause the same issues, but I can't totally rule out delay due to
network transport time influencing the frequency of the problem (if I
could rule that out I'd probably be able to solve the issue 8-))..

Thanks for helping out with this.

John, got your package. Of course with just sqlite it is just blocking, so I need to get 
postgresql running next in order to try to reproduce the issue.

John, 
I can now see the behaviour your are refering to. However I do not
yet fully understand it. Using your email script I get:


SENDMAILDEBUG=1 PYTHONPATH="$PWD" python 
roundup/scripts/roundup_mailgw.py demo < email_1
tx_SourceCheckAudit(None) pre db.tx_Source: email, nonce: 
35cac65328bed1477b21
tx_SourceCheckAudit(None) post db.tx_Source: email, nonce 
35cac65328bed1477b21
tx_SourceCheckAudit(1) pre db.tx_Source: email, nonce: 
cdc748bdd843bd708bbc
tx_SourceCheckAudit(1) post db.tx_Source: email, nonce 
cdc748bdd843bd708bbc
tx_SourceCheckReact(1) pre db.tx_Source: email, recorded: arrived via: email 
cdc748bdd843bd708bbc
tx_SourceCheckReact(1) post db.tx_Source: email, recorded: arrived via: email 
cdc748bdd843bd708bbc

The history will only mark the changes done to the "issue" object,
I wonder if there is a mixup between the values of tx_Source
for "issue" and "msg" somehow in the way how this is implemented.
Just an idea. My next step is trying to understand how this all
is supposed to work.

Hi Bernhard:

In message <1357335794.31.0.436770561715.issue2550731@psf.upfronthosting.co.za>
 <1357335794.31.0.436770561715.issue2550731@psf.upfronthosting.co.za>,
Bernhard Reiter writes:
>Bernhard Reiter added the comment:
>I can now see the behaviour your are refering to.

Good, so it's not just me 8-).

(note to people reading this on the tracker, Bernhard has test
environment with a test tracker, sample email meabssages etc that will
be uploaded here at some point).

>However I do not yet fully understand it. Using your email script I get:
>
>SENDMAILDEBUG=1 PYTHONPATH="$PWD" python 
>roundup/scripts/roundup_mailgw.py demo < email_1
>tx_SourceCheckAudit(None) pre db.tx_Source: email, nonce: 
>35cac65328bed1477b21
>tx_SourceCheckAudit(None) post db.tx_Source: email, nonce 
>35cac65328bed1477b21
>tx_SourceCheckAudit(1) pre db.tx_Source: email, nonce: 
>cdc748bdd843bd708bbc
>tx_SourceCheckAudit(1) post db.tx_Source: email, nonce 
>cdc748bdd843bd708bbc

Actually you should see only one pair of audit calls, I am not sure
why there are two pairs. And the first pair looks like it's creating a
new issue not changing issue 1.

>tx_SourceCheckReact(1) pre db.tx_Source: email, recorded: arrived via: email
> 
>cdc748bdd843bd708bbc
>tx_SourceCheckReact(1) post db.tx_Source: email, recorded: arrived via: email 
>cdc748bdd843bd708bbc
>
>The history will only mark the changes done to the "issue" object,
>I wonder if there is a mixup between the values of tx_Source
>for "issue" and "msg" somehow in the way how this is implemented.

Just FYI I didn't implement any tx_Source for the message when I first
saw the journal mixing up changes. I put the tx_Source in the schema
because my plan is to also record the tx_Source for messages so I can
send messages:

  "this arrived via email" (sending via email)

  "this arrived via web"  (sending via the xmlrpc or web interface)

to the ticket and verify the value of tx_Source against the message
contents. If the message says it arrived via email and tx_Source says
email, then having the journal report the message arrived via web
means it's a ournal issue and the code is getting the right tx_Source
to the detectors.

If the detectors are getting the wrong tx_Source info and we are
making security decisions on the basis of that info then the code is
worse than worthless.

>Just an idea. My next step is trying to understand how this all
>is supposed to work.

Yeah that's sort of where I fell down. I tried tracing through it with
the python debugger, but that effectively serialized the transactions
and I didn't see the scrambled info in the journal 8-(.

Even when seeing the bad behaviour, when looking at all "msg" objects
(using roundup-admin      table msg ) they all have a correct tx_Source
value.

In trying to see better what is going one, I've made a difference between
being called as "set" or "create":


diff -r 26a138760969 detectors/txSource_detector.py
--- a/detectors/txSource_detector.py    Wed Jan 02 22:26:31 2013 +0100
+++ b/detectors/txSource_detector.py    Fri Jan 04 23:32:37 2013 +0100
@@ -38,6 +38,10 @@
     # if db.tx_Source == "email":
     #    raise Reject, 'Change not allowed via email'
 
+def txSourceCheckAuditSet(db, cl, nodeid, newvalues):
+    print "called on 'set'"
+    return txSourceCheckAudit(db, cl, nodeid, newvalues)
+
 def txSourceCheckReact(db, cl, nodeid, oldvalues):
     ''' An reactor to print the value of the source of the
         transaction that trigger this change. The sleep call
@@ -54,8 +58,12 @@
     time.sleep(10)
     print "txSourceCheckReact(%s) post db.tx_Source: %s"%(nodeid, 
db.tx_Source)
 
+def txSourceCheckReactSet(db, cl, nodeid, oldvalues):
+    print "called on 'set'"
+    return txSourceCheckReact(db, cl, nodeid, oldvalues)
+
 def init(db):
-    db.issue.audit('set', txSourceCheckAudit)
+    db.issue.audit('set', txSourceCheckAuditSet)
     db.issue.audit('create', txSourceCheckAudit)
-    db.issue.react('set', txSourceCheckReact)
+    db.issue.react('set', txSourceCheckReactSet)
     db.issue.react('create', txSourceCheckReact)

Okay, here is my analysis:

I've enabled the debug output of the database, by setting
the following in demo/config.ini: 
  level = DEBUG

Actually I could reproduce this quite often with the local database.
The log with my first run is in bad_run.txt,
then I've rectified the debugging output and added some more,
see my hg export 
  issue2550731-better-debugging-20130105ber1.patch
which is on top of John's "test" environment, but you'll get the idea.
This resulted in bad_run2.txt, where I did at least see one race condition.
In function set_inner() the previous node is the same both times,
this is because it is read before the first change is made to it.
See my comments within bad_run2.txt.
Looks like this needs some better locking during the transaction:
Once you read with the intention to update, you need to block other processes 
with the same goal.

It may not be the only problem, thought. I haven't fully groked set_inner() yet,
it feels a bit suspicious to me that the journal value is getting the old one and 
keeping it for String as well. Other types change it. But if this is broken, then a lot 
more history for strings would not work in all cases, which seems unlikely.

Here is how the history looks like after the bad run:
2013-01-05 01:15:53	demo	set	messages: + msg11
tx_Source: arrived via: web 98cb97ac062e09f6dd61 -> arrived via: web 
34f06fe3e5338455d1a0
2013-01-05 01:15:43	user4	set	messages: + msg10
tx_Source: arrived via: web 98cb97ac062e09f6dd61 -> arrived via: web 
98cb97ac062e09f6dd61
keyword: + keyword1
2013-01-05 01:13:41	demo	set	status: unread -> chatting
messages: + msg9
tx_Source: arrived via: web 2987d3b6de54562dda21 -> arrived via: web 
98cb97ac062e09f6dd61
2013-01-04 00:08:31	admin	create

In message <1357350203.18.0.396444462484.issue2550731@psf.upfronthosting.co.za>
 <1357350203.18.0.396444462484.issue2550731@psf.upfronthosting.co.za>,
Bernhard Reiter writes:
>Looks like this needs some better locking during the transaction:
>Once you read with the intention to update, you need to block other processes 
>with the same goal.

This explains the observation that the problem doesn't happen with
sqlite or bsddb back ends right? Their nature serializes the database
access, so there is an implicit lock that prevents multiple processes
from opening the database in update mode at the same time.

-- rouilj

Yes,I believe the observed race condition is to blame for at least a part
of the problem. If this hypothesis holds, then if would mean this is independent
from your patch, though. We'e probably should bring it up in a different issue
and find a way to demonstrate it with a regular version of roundup.
Note that this race condition is in rdbms_common.py,
but back_mysql.py overrides the function and seems to deal 
at least with one concurrent write situation.

It would mean that some decisions based on auditors or reactors may be wrong
in a concurrent edit situation for postgresql.

Still I believe this code is strange:
            current = node.get(propname, None)
            if value == current:
                del propvalues[propname]
                continue
            journalvalues[propname] = current

shouldn't it be 
  journalvalues[propname] = value 
instead of "current"?

In message <1357499750.81.0.443026588007.issue2550731@psf.upfronthosting.co.za>
 <1357499750.81.0.443026588007.issue2550731@psf.upfronthosting.co.za>,
Bernhard Reiter writes:
>Bernhard Reiter added the comment:
>Yes,I believe the observed race condition is to blame for at least a part
>of the problem. If this hypothesis holds, then if would mean this is
>independent from your patch, though. We'e probably should bring it
>up in a different issue and find a way to demonstrate it with a
>regular version of roundup.

Agreed. I think interleving two commits that change the same fiend in
the same issue with a mysql/postgresql back would do it.

>Note that this race condition is in rdbms_common.py,
>but back_mysql.py overrides the function and seems to deal 
>at least with one concurrent write situation.

Actually it looks like back_mysql deals only with the case where a new
object/node is created. An example race is:

  tx 1 checks to see if an issue with the new issue name/handle is present
    in the db. The handle is available.
  tx 2 checks to see if an issue with the new issue name/handle is present
    in the db. The handle is available.
  tx 1 create a new issue using the name/handle. Success.
  tx 2 creates a new issue using the handle, fails because the handle
    was created by tx1.

I think this case will result in a traceback in the postgres case, but
that depends on the underlying sql that is produced. If the generated
does an insert rather than an insert and on error update, I hope it
will boow up in psycop2. Creating an issue to verify that this case is
handled "correctly" by failing and then making sure a clean
non-traceback result is returned to the user would be good.

>It would mean that some decisions based on auditors or reactors may be wrong
>in a concurrent edit situation for postgresql.
>
>Still I believe this code is strange:
>            current = node.get(propname, None)
>            if value == current:
>                del propvalues[propname]
>                continue
>            journalvalues[propname] = current

I was looking at that code as a possible race condition as the
node.get may get a value that changes during the lifetime of the
transaction. Consider:

 database has prop 1 set to A 
 tx 1: sets prop 1 to B
 tx 2: doesn't change prop 1 keeping it at A

 what happens after tx 2 completes?

 if tx1 commits before tx2 hits this code, it looks like tx 2
   changed prop 1 from B to A. The end state is prop 1 = A.

 if tx2 passes through this code before tx1 hits this code we end up
   with prop 1 changed to B on tx 1. The end state is prop 1 = B

I am not sure what should happen there exactly.

>shouldn't it be 
>  journalvalues[propname] = value 
>instead of "current"?

I think journalvalues is recording the old values and passed as props
on a call to self.db.addjournal -> doSaveJournal. If not journaling
would be totally broken and this part of code has been around since
the 0.5 release according to hg blame and hg log.

Also the same code shows up in back_anydbm.py.

On Sun, Jan 06, 2013 at 10:41:19PM +0000, John Rouillard wrote:
> 
> In message <1357499750.81.0.443026588007.issue2550731@psf.upfronthosting.co.za>
>  <1357499750.81.0.443026588007.issue2550731@psf.upfronthosting.co.za>,
> Bernhard Reiter writes:
> >Bernhard Reiter added the comment:
> >Yes,I believe the observed race condition is to blame for at least a part
> >of the problem. If this hypothesis holds, then if would mean this is
> >independent from your patch, though. We'e probably should bring it
> >up in a different issue and find a way to demonstrate it with a
> >regular version of roundup.
> 
> Agreed. I think interleving two commits that change the same fiend in
> the same issue with a mysql/postgresql back would do it.

I don't think this is true, there are different strategies for
RDBMSes how they handle concurrency:
- Use locking and don't allow concurrent updates
  (done by mysql and sqlite)
- Allow concurrent updates and roll back one of the transactions
  if updates collide (done by PostgreSQL)

Now if we would decide to do locking in userspace this would defeat the
whole database implementation.

Concurrent updates *can* be a problem if we are using side-effects (e.g.
sending email) before we know that a transaction will succeed.

AFAIK roundup currently runs the code of the auditors in the same
transaction as the reactors and if a reactor fails the whole thing
is rolled back. This can be a problem because side-effects are not
rolled back. I'm open for doing a commit after the auditors and run the
reactors in a separate transaction. This would still not solve
side-effect issues, though.

> Actually it looks like back_mysql deals only with the case where a new
> object/node is created. An example race is:
> 
>   tx 1 checks to see if an issue with the new issue name/handle is present
>     in the db. The handle is available.
>   tx 2 checks to see if an issue with the new issue name/handle is present
>     in the db. The handle is available.
>   tx 1 create a new issue using the name/handle. Success.
>   tx 2 creates a new issue using the handle, fails because the handle
>     was created by tx1.

If you mean by "handle" the id of the new issue: No this is not a problem.
Postgres and MySQL support sequences, each of the transactions above
would obtain a separate sequence number which is used as the new id. The
database code guarantees that these are unique.

You can have problems if you do some checks on issue creation in
userspace (e.g. you want to make sure that a certain issue property is
not in the database): In that case the scenario above will come true
because in concurrent updates you see only the database status at the
start of the current transaction. In that case both checks on uniqueness
in userspace will return "ok" and both transactions will go through.
Thats why databases use uniqueness constraints.

> I think this case will result in a traceback in the postgres case, but
> that depends on the underlying sql that is produced. If the generated
> does an insert rather than an insert and on error update, I hope it
> will boow up in psycop2. Creating an issue to verify that this case is
> handled "correctly" by failing and then making sure a clean
> non-traceback result is returned to the user would be good.

See above: I'm sure that normal issue creation is not subject to
concurrency problems. Doing two concurrent updates on the same properties
of the same issue *will* produce one failing transaction in postgres,
though.

> >It would mean that some decisions based on auditors or reactors may be wrong
> >in a concurrent edit situation for postgresql.

See above: Yes if these have side-effects or you have "hand-coded"
uniqueness constraints checked in userspace.

> Consider:
> 
>  database has prop 1 set to A 
>  tx 1: sets prop 1 to B
>  tx 2: doesn't change prop 1 keeping it at A
> 
>  what happens after tx 2 completes?
> 
>  if tx1 commits before tx2 hits this code, it looks like tx 2
>    changed prop 1 from B to A. The end state is prop 1 = A.
> 
>  if tx2 passes through this code before tx1 hits this code we end up
>    with prop 1 changed to B on tx 1. The end state is prop 1 = B
> 
> I am not sure what should happen there exactly.

The database-behavior of the example above depends on what tx1 and tx2
*read* and *write*: If tx2 doesn't read prop1, *and* (as you implied)
doesn't *write* prop1, tx1 will still "win" and change prop-1 to B. The
two transactions are independent in this case and will both go through.

Note that roundup will always read *all* properties of an issue,
even if you do a p = db.issue.get (id, 'property') this will do
a db.issue.getnode (id) behind the scenes. So my scenario above will
never come true in roundup if both transactions read the same issue.

If tx2 *reads* prop-1 and is selected by the database to win the race,
tx1 is rolled back (because other properties written by tx2 could be
based on the value prop-1). See my example session below (you can try
this yourself).

Roundups implementation makes sure (since some time ago I fixed this)
that no properties are cached beyond transactions: The database needs to
see the writes *and* the reads to the database to decide if transactions
collide.

Example concurrent sessions:

Session 1                               Session 2
>>> import os                           >>> import os
>>> from roundup import instance        >>> from roundup import instance
>>> dir     = os.getcwd ()              >>> dir     = os.getcwd ()
>>> tracker = instance.open (dir)
                                        >>> tracker = instance.open (dir)
>>> db      = tracker.open ('admin')
                                        >>> db      = tracker.open ('admin')
>>> i = db.issue.getnode ('1')          
                                        >>> i = db.issue.getnode ('1')
>>> db.issue.set ('1', title = "HUHU")
                                        >>> db.issue.set ('1', title = "HUHU")
                                        [hangs]
>>> db.commit ()
                                        Traceback (most recent call last):
                                        ...
                                        psycopg2.extensions.TransactionRollbackError: could not serialize access due to concurrent update

Note that I'm seeing these errors about once per month in a very
busy tracker.

Far more often transactions are rolled back because roundup caches the
session cookies and updates them in the same transaction as the actual
data modifications... I think we still have an open issue on that.

It is implemented for quite some time now that roundup will display an
error if it detects that since the browser loaded an issue someone else
updated it and now a change based on an earlier version is submitted. We
probably should display the same error in case of real concurrency errors
from the database in that case.

Ralf
-- 
Dr. Ralf Schlatterbeck                  Tel:   +43/2243/26465-16
Open Source Consulting                  www:   http://www.runtux.com
Reichergasse 131, A-3411 Weidling       email: office@runtux.com
osAlliance member                       email: rsc@osalliance.com

On Mon, Jan 07, 2013 at 09:18:17AM +0000, Ralf Schlatterbeck wrote:
> Example concurrent sessions:
Sorry I failed when transcribing this. The updated property is different
in both sessions, in Session 2 I've updated the property "release" not
"title":

Session 1                               Session 2
>>> import os                           >>> import os
>>> from roundup import instance        >>> from roundup import instance
>>> dir     = os.getcwd ()              >>> dir     = os.getcwd ()
>>> tracker = instance.open (dir)
                                        >>> tracker = instance.open (dir)
>>> db      = tracker.open ('admin')
                                        >>> db      = tracker.open ('admin')
>>> i = db.issue.getnode ('1')          
                                        >>> i = db.issue.getnode ('1')
>>> db.issue.set ('1', title = "HUHU")
                                        >>> db.issue.set ('1', release = "23")
                                        [hangs]
>>> db.commit ()
                                        Traceback (most recent call last):
                                        ...
                                        psycopg2.extensions.TransactionRollbackError: could not serialize access due to concurrent update

The important point here is that Session 2 is rolled back because setting
the release *could* depend on the property "title" written by Session 1.
The SQL machinery notes that the transaction of Session 2 reads all the
properties of issue1 and detects that they *could* conflict.

Ralf
-- 
Dr. Ralf Schlatterbeck                  Tel:   +43/2243/26465-16
Open Source Consulting                  www:   http://www.runtux.com
Reichergasse 131, A-3411 Weidling       email: office@runtux.com
osAlliance member                       email: rsc@osalliance.com

> The patch file for roundup is on the the issue already and the
> additional detector change and the problem I see is described at:
> 
>   http://sourceforge.net/mailarchive/message.php?msg_id=29359236

Is it correct that your detector is an auditor and no reactor?

I think I know why you're seeing that behaviour:
you are not looking at the old title, that means the database system is
free to set the title to the title set by one of the parallel
transactions it chooses as the "winner". This is the one you're seeing in
the history for all the other transactions.

Some of the title updates will never make it to the database. All of your
parallel transactions will get the same old value of the title.

Only the value present in the title at the start of the current
transaction is later logged to the history. This is the same for all the
transactions started at the same time.

Since your updates to the title are not based on any values in the
database, your transactions are trivially serializable (the db may just
chose one of the transactions which it declares the last writer and
ignore all the others).

Sometimes serialisation of database actions are not very intuitive :-)

To get the correct behaviour you'll have to tell the DB that you are
modifying the title based on the previous one. This means in the auditor
you should first get the old title with

t = db.issue.get (nodeid, 'title')

then rewrite it as indicated in the message given above.

This *will* probably produce tracebacks indicating concurrency problems.

That said: Testing your new mechanism via history logs is probably not
the way to go if you additionally want to do this in parallel because the
history reflects only the title at the start of the transaction and some
titles will never make it to the history.

It is probably still ok to draft a (non-concurrent) regression test that
updates the title with the value passed and checks that it is updated
correctly.

As you noted: The messages printed indicate the correct value.

Ralf
-- 
Dr. Ralf Schlatterbeck                  Tel:   +43/2243/26465-16
Open Source Consulting                  www:   http://www.runtux.com
Reichergasse 131, A-3411 Weidling       email: office@runtux.com
osAlliance member                       email: rsc@osalliance.com

Hi Ralf,
thanks for looking into this issue. I don't have much experience in this part
of roundup's code, so your input is highly appreciated. I am just trying
John to get this resolved. 

A few thoughts (thought I know I have not understood everything):
To me it does not make sense what I have seen and what you - Ralf - describe
how it should work. John gave me a test case and the behaviour is surprising
and unwanted as far as I can say. Even with my ideas of a transaction.
John gave me a test case with tx_Source being an attribute to msg and 
issue which is manipulated by an auditor. 
John, please publish this testcase or an improved one.

When running with postgresql, the problem is that the history is not set
to the right value. Yes, I would expect a locking mechanism in the database
to prevent this, a transaction would be cool. However it does not prevent it.
Maybe that is the result of line 2996 of rdbms_common.py:
   oldvalues = copy.deepcopy(self.db.getnode(self.classname, itemid))

The msql prevention of the same id on new nodes is probably something 
unrelated. (I've only mentioned it because it made me think why postgresql does 
not have such special code.)

I've not fully grasped how the journal should work, so I'm unsure about
what should be saved, however there is special code for other types than
String that will save the new values.

If we do have a transaction thing already going on and the behaviour is 
explainable then it is underdocumented, because it would mean special 
requirements for auditors.
  





  

The problem is that the code of set_inner()

On Mon, Jan 07, 2013 at 08:46:19PM +0000, Bernhard Reiter wrote:
> When running with postgresql, the problem is that the history is not set
> to the right value. Yes, I would expect a locking mechanism in the database
> to prevent this, a transaction would be cool. However it does not prevent it.
> Maybe that is the result of line 2996 of rdbms_common.py:
>    oldvalues = copy.deepcopy(self.db.getnode(self.classname, itemid))

Yes, if this happens outside the transaction this could be the reason
that all the transactions get the same history. If it happens inside the
transaction postgres should note that the issue is *read* and see a
conflict.

I think I'll have to look into this more closely...

Ralf

Am Mittwoch, 9. Januar 2013 09:12:00 schrieb Ralf Schlatterbeck:
> I think I'll have to look into this more closely...

Highly appreciated as it blocks John's change to progress.

In message <20130109081141.GA21559@runtux.com> <20130109081141.GA21559@runtux.c
om>,
Ralf Schlatterbeck writes:
>I think I'll have to look into this more closely...

Ralf, I have attached the test tracker tarball I sent to Bernhard. It
includes the auditor and reactor that Bernhard started with.

In an earlier email you asked if it was just an auditor and the answer
is no it is both an auditor and reactor.  But the auditor *does not*
call a get on the database. It just uses the info passed to it in the
db.tx_Source string.

Did I understand you correctly when you indicated that doing a
cl.get(nodeid, 'tx_Source') in the auditor would cause parallel update
transactions to realize they are stepping on each each other and cause
a conflict warning.

In any case the instructions for using the tarball with the test
tracker and the exported test data are:
===========

You should be able to untar the tarball at the top of a roundup
development tree (I am using one with Bernhard's patch applied to
it). It will create the new test template
(share/roundup/templates/test) and the directory demo.exp.

  python demo.py -t test ...

should get you a working tracker. Exit the server and then use:

 PYTHONPATH="$PWD" python  roundup/scripts/roundup_admin.py -i demo
 import demo.exp
 commit
 exit

should get you 4 users and 4 issues and 4 keywords that you can use to
test.

Then restart the demo tracker web interface and make a change to one
of the issues.

Then change the issue in the web interface and via the email interface
and sumit them at the same time. If you try that enough times, in the
journal you will see it get confused and group the change that arrived
via email with a tx_Source that says web.

contents of email_1:
====
From: user4
Subject: [issue4] issue4 [keyword=+keyword1]

====

Email submission can be done using:

  SENDMAILDEBUG=1 PYTHONPATH="$PWD" python roundup/scripts/roundup_mailgw.py demo < email_1

Each change should result in output from the tx_source_detector of the
form:

  tx_SourceCheckAudit(1) pre db.tx_Source: cli, nonce: 84a7b7fe7e99b584f2a3
  tx_SourceCheckAudit(1) post db.tx_Source: cli, nonce 84a7b7fe7e99b584f2a3
  tx_SourceCheckReact(1) pre db.tx_Source: cli, recorded: arrived via: cli 84a7b7fe7e99b584f2a3
  tx_SourceCheckReact(1) post db.tx_Source: cli, recorded: arrived via: cli 84a7b7fe7e99b584f2a3

where pre/post occur before and after a 10 second sleep in the
detector allowing multiple changes to overlap. As you can see above
this change was done to issue 1 (number in parens above) using the cli.

The nonce is a random (and hopefully unique) value to identify the
transaction as it passes through the detectors.

In the history this looks like:

  2013-01-04 01:18:24	admin	set	tx_Source: arrived via: web c05d48aea9f81a9ae254 -> arrived via: cli 84a7b7fe7e99b584f2a3
     keyword: + keyword2

with multiple changes in flight at the same time, we end up with the
journal tx_Source not matching the method by which the change
occurred, and that's the bug.
==========

Am Mittwoch, 9. Januar 2013 16:00:26 schrieb John Rouillard:
> But the auditor *does not*
> call a get on the database. It just uses the info passed to it in the
> db.tx_Source string.

Which I believe should be okay for doing decisions in principle, 
there shouldn't be a necessity to explicitely "read" all the values
in order to lock them when basing decisions on them.

> Did I understand you correctly when you indicated that doing a
> cl.get(nodeid, 'tx_Source') in the auditor would cause parallel update
> transactions 

Also here, the roundup code itself does the wrong history entry.

>   python demo.py -t test ...

Don't forget to use the right backend, if your postgresql
can be accessed by the tests then the demo app can also use it
  python demo.py -t -b postgresql nuke

In message <201301091744.54722.bernhard@intevation.de>
<201301091744.54722.bern hard@intevation.de>, Bernhard Reiter writes:
>Bernhard Reiter added the comment:
>Am Mittwoch, 9. Januar 2013 16:00:26 schrieb John Rouillard:
>> But the auditor *does not*
>> call a get on the database. It just uses the info passed to it in the
>> db.tx_Source string.
>
>Which I believe should be okay for doing decisions in principle, 

I agree. I think the original goal to allow the auditor to make a
decision based on the method by which an update arrived is working
fine. Now that we know why the journal anomolies are occurring I think
I am ok with saying it's not a bug in the code I wrote.

>there shouldn't be a necessity to explicitely "read" all the values
>in order to lock them when basing decisions on them.

If the auditor needs to know the current value from the database
(e.g. in moving between statuses in a workflow) then it can do the
read of the existing status and get the lock.

>> Did I understand you correctly when you indicated that doing a
>> cl.get(nodeid, 'tx_Source') in the auditor would cause parallel update
>> transactions 

If this get "solves" the journaling problem, we could always do the
get in the demo auditor for the side effect of fixing the journal
entry.

I think we should split out the problem that the history is not kept
consistent with parallel changes of a node. It is separate from the problem 
of recognising where a change comes from. And it is an important issue, 
because data is lost. Some in-between states may not recorded and they 
may hold important data for the history, depending on how the tracker is 
used.

Ralf, what do you think?

On Thu, Jan 17, 2013 at 09:19:25PM +0000, Bernhard Reiter wrote:
> 
> Bernhard Reiter added the comment:
> 
> I think we should split out the problem that the history is not kept
> consistent with parallel changes of a node. It is separate from the problem 
> of recognising where a change comes from. And it is an important issue, 
> because data is lost. Some in-between states may not recorded and they 
> may hold important data for the history, depending on how the tracker is 
> used.
> 
> Ralf, what do you think?

You mean we should put that into its own issue? Yes, please, good idea.

Thanks,
Ralf

So are we agreed that this is the todo list:

 1) Create a new issue dealing with the problem where parallel
    journal updates do not properly track all changes to an issue.

 2) Commit this patch to the code for release and review.
    I need to write up a changelog entry and an example
    auditor.

  3) Close out this ticket as resolved.

Also it would be nice if the tracker had a see also to go along
with dependencies and superseder where we can record the issue generated
by item 1 against this ticket.

-- rouilj

> So are we agreed that this is the todo list:
>
>  1) Create a new issue dealing with the problem where parallel
>     journal updates do not properly track all changes to an issue.

Yes.

>  2) Commit this patch to the code for release and review.
>     I need to write up a changelog entry and an example
>     auditor.

I think Ralf already said, he wanted it in.
Given my staring on the OpenPGP code part, I doubt that it works
in all situations. That would need a test. But again, this should not
stop you submitting the code as it needs more testing. Maybe you 
should label the OpenPGP support experimental.

>   3) Close out this ticket as resolved.

> Also it would be nice if the tracker had a see also to go along
> with dependencies and superseder where we can record the issue generated
> by item 1 against this ticket.

(should probably discussed elsewhere ;) )

On Mon, Feb 04, 2013 at 09:33:43AM +0000, Bernhard Reiter wrote:
> 
> Bernhard Reiter added the comment:
> 
> > So are we agreed that this is the todo list:
> >
> >  1) Create a new issue dealing with the problem where parallel
> >     journal updates do not properly track all changes to an issue.
> 
> Yes.
> 
> >  2) Commit this patch to the code for release and review.
> >     I need to write up a changelog entry and an example
> >     auditor.
> 
> I think Ralf already said, he wanted it in.

Yes, but didn't have the time to do it myself yet.

> Given my staring on the OpenPGP code part, I doubt that it works
> in all situations. That would need a test.

Yes, I guess the OpenPGP code *is* experimental although there are some
tests. I had problems when trying this out with a customer and I didn't
debug this yet.

> But again, this should not
> stop you submitting the code as it needs more testing. Maybe you 
> should label the OpenPGP support experimental.

Yes, I think that shouldn't stop us from committing this.

Ralf
-- 
Dr. Ralf Schlatterbeck                  Tel:   +43/2243/26465-16
Open Source Consulting                  www:   http://www.runtux.com
Reichergasse 131, A-3411 Weidling       email: office@runtux.com
allmenda.com member                     email: rsc@allmenda.com

Am Montag, 4. Februar 2013 11:01:39 schrieb Ralf Schlatterbeck:
> > Given my staring on the OpenPGP code part, I doubt that it works
> > in all situations. That would need a test.
>
> Yes, I guess the OpenPGP code *is* experimental although there are some
> tests. I had problems when trying this out with a customer and I didn't
> debug this yet.

My comment was specific to the detect-the-source-from-OpenPGP functionality.
(As for general OpenPGP support, let us open new issues or discuss on devel.
Have you seen my commit two weeks ago or so)

As requested by Bernhard Reiter on the roundup-dev list, I am
attaching a patch that can be applied to a current roundup mercurial
checkout from:

  ssh://<user>@roundup.hg.sourceforge.net/hgroot/roundup/roundup

This patch adds support for tx_Source and patches the tests to test
this functionality.

I am having issues with getting the test_xmlrpc to work with the
sqlite backend. It seems that regardless of where I put the schema
changes in the file they are wiped out by the time the tests run.

There are a couple of failure with the sqlite backend. One example is:

Error in test testAuthFilter (test.test_xmlrpc.TestCase_sqlite)
Traceback (most recent call last):
  File "/usr/lib/python2.7/unittest/case.py", line 327, in run
    testMethod()
  File "/home/rouilj/develop/roundup.tx_Source/./test/test_xmlrpc.py",
line 180, in testAuthFilter
    issue.create(title='i1', status=open, keyword=[d2])
  File
"/home/rouilj/develop/roundup.tx_Source/./roundup/backends/rdbms_common.py",
line 1502, in create
    newid = self.create_inner(**propvalues)
  File
"/home/rouilj/develop/roundup.tx_Source/./roundup/backends/rdbms_common.py",
line 1640, in create_inner
    self.db.addnode(self.classname, newid, propvalues)
  File
"/home/rouilj/develop/roundup.tx_Source/./roundup/backends/rdbms_common.py",
line 958, in addnode
    self.sql(sql, vals)
  File
"/home/rouilj/develop/roundup.tx_Source/./roundup/backends/rdbms_common.py",
line 221, in sql
    cursor.execute(sql, args)
OperationalError: table _issue has no column named _tx_Source

while the test using the anydbm back end:

  testAuthFilter (test.test_xmlrpc.TestCase_anydbm) ... ok

passes.

All of the rest of the tests work although I have had to set
db.tx_Source in some of the tests and this seems wrong. At least it
tests the code path through the detector and makes sure that the
auditor and reactors paths are working properly.

Note that an alternate configuration of these tests used a custom
tracker with detectors and schema changes. With this alternate
tracker, all the tests pass including test_xmlrpc, so AFAICT the
xmlrpc tests should pass if I can get the schema set up correctly.

I have not tested the postgres or mysql backends so this may be
generic issue with sql backends.

I've split out issue2550806 (Parallel change requests to properties from auditors 
may lead to data loss).

John, if you haven't checked postgresql or mariadb yet, you would try and could 
reduce the problem space to sqlite only.

I also get an error with postgresql.

 LANG=en_US python run_tests.py . testAuthFilter

ERROR: testAuthFilter (test.test_xmlrpc.TestCase_sqlite)
OperationalError: table _issue has no column named _tx_Source
ERROR: testAuthFilter (test.test_xmlrpc.TestCase_postgresql)
ProgrammingError: column "_tx_source" of relation "_issue" does not exist
LINE 1: ...nedto,_creation,_creator,_priority,_status,_title,_tx_Source...
 
More details:
  rm -r tmpdb/
  mkdir tmpdb
  initdb -D tmpdb/ -U rounduptest --locale=c --encoding=UTF8
   pg_ctl -D tmpdb/ -l logfile -o '-k ./' start


=========================================================
=============
ERROR: testAuthFilter (test.test_xmlrpc.TestCase_postgresql)
----------------------------------------------------------------------
Traceback (most recent call last):
  File ".../python2.7/unittest/case.py", line 327, in run
    testMethod()
  File ".../test/test_xmlrpc.py", line 180, in testAuthFilter
    issue.create(title='i1', status=open, keyword=[d2])
  File ".../roundup/backends/rdbms_common.py", line 1502, in create
    newid = self.create_inner(**propvalues)
  File ".../roundup/backends/rdbms_common.py", line 1640, in create_inner
    self.db.addnode(self.classname, newid, propvalues)
  File ".../roundup/backends/rdbms_common.py", line 958, in addnode
    self.sql(sql, vals)
  File ".../roundup/backends/rdbms_common.py", line 221, in sql
    cursor.execute(sql, args)
ProgrammingError: column "_tx_source" of relation "_issue" does not exist
LINE 1: ...nedto,_creation,_creator,_priority,_status,_title,_tx_Source...
                                                             ^

John, adding a call to " self.db.post_init()" after adding the properties to the objects 
make the tests run fine for me. See the example in db_test_base.py.

HTH, Bernhard

In message
<1366745212.66.0.999759047942.issue2550731@psf.upfronthosting.co.za>
<1366745212.66.0.999759047942.issue2550731@psf.upfronthosting.co.za>,
Bernhard Reiter writes:

>Bernhard Reiter added the comment:
>
>John, adding a call to " self.db.post_init()" after adding the
>properties to the objects make the tests run fine for me. See
>the example in db_test_base.py.

I'll try it tonight when I get home. I know I added db.commit() and I
am pretty sure I used db.post_init() (following the code in
db_test_base.py:setupSchema) as well.

Maybe I just didn't have the schema changes and the post_init call
arranged properly to work.

For those following along at home from hyperdb.py:

     def post_init(self):
        """Called once the schema initialisation has finished.
           If 'refresh' is true, we want to rebuild the backend
           structures.
        """
        raise NotImplementedError

The version in anydbm (roundup/backends/back_anydbm.py using the db
file structure) only reindexes data. It doesn't have any code that
handles schema changes. Since I had no data to reindex at that point,
this test passed.

However post_init from roundup/backends/rdbms_common.py which is used
by postgres and sqlite does update tables and things based on schema
changes hence the reason the sqlite and postgres tests failed.

Thanks for looking at this Bernhard.

Hopefully there will be a commit coming soon.

I just pushed the changes to the master repo. I am not quite sure
I did it right as I had already committed my changes before I
realized there were updates in the master repo. So I did a:

  hg pull
  hg merge
  hg ci
  hg push

to get my changes mixed into the current master code.
But at least the changes are in the master repo for your
enjoyment.

* John Rouillard <issues@roundup-tracker.org> [20130424 05:18]:
> I just pushed the changes to the master repo. I am not quite sure
> I did it right as I had already committed my changes before I
> realized there were updates in the master repo. So I did a:
> 
>   hg pull
>   hg merge
>   hg ci
>   hg push
> 
> to get my changes mixed into the current master code.
> But at least the changes are in the master repo for your
> enjoyment.

This is the correct action and your merge looks fine.

Thanks for this feature, I think this will allow me to fix a problem
I have in a customized setup.

Regards,
Thomas

John, you are welcome. Thanks for committing the change and for creating
it in the first place.