[Nitro] Request for Transaction example

Reid Thompson Reid.Thompson at ateb.com
Tue Jun 5 09:08:21 EDT 2007


On Tue, 2007-06-05 at 08:26 +0300, Jonathan Buch wrote:
> Hi,
> 
> > It still appears to be committing on each save -- if all records were in
> > a single transaction, no rows should be present until the final commit
> > -- correct????
> >
> > yet...
> 
> that I don't know, have you watched the sql output?  That's the best
> way to make sure everything's alright.  `$DBG = true` somewhere above
> Og.start will do.  With 32k entries it'll be a little messy, but you
> can redirect your output to a file I guess.  :)
> So, the first sql statement (after starting up Og) should be a begin
> transaction.
> 
> There's all kinds of transaction 'levels', read
> http://www.postgresql.org/docs/8.0/static/transaction-iso.html
> for more information.  It says 'read committed' is the standard level,
> but it might be uncommitted for you, if you can select stuff while
> transaction is still in progress.
> 
> But, if there's no TRANSACTION at the beginning, then there's something
> wrong within Og.
> 
> Jo
> 
Ok - looks to me like something is broken then.  Can anyone confirm the
following...( more notes inline  )

One thing that I note is that the postgresql log shows all the sql
statements from the psql test ending with a 
';' but none of the Og statements end with ';' in the postgresql log.  I
believe the BEGIN TRANSACTION is failing because it is not terminated
with a ';'?

Turning $DBG=true and logging to file...
snippet of scripts log file...let it run for a bit, then CTRL-C'd the script

 INFO: Og uses the Postgresql store.
 INFO: Created table 'tbltest'.
DEBUG: BEGIN TRANSACTION
DEBUG: SELECT nextval('tbltest_oid_seq')
DEBUG: INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '08:00:53', 'BUSY', '[123456789]', '[SE]', '[566]', 1, '[01]', '2007/01/02', '[62]')
DEBUG: SELECT nextval('tbltest_oid_seq')
DEBUG: INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '08:00:53', 'SITTONE', '[123456789]', '[SE]', '[569]', 2, '[01]', '2007/01/02', '[48]')
DEBUG: SELECT nextval('tbltest_oid_seq')
DEBUG: INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '08:00:54', 'BUSY', '[123456789]', '[SE]', '[566]', 3, '[01]', '2007/01/02', '[62]')
DEBUG: SELECT nextval('tbltest_oid_seq')
DEBUG: INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '08:00:57', 'BUSY', '[123456789]', '[SE]', '[566]', 4, '[01]', '2007/01/02', '[62]')
DEBUG: SELECT nextval('tbltest_oid_seq')
....
....
DEBUG: INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '09:00:21', 'ANSM_LEFTMSG', '[123456789]', '[X2]', '[CPE]', 2056, '[01]', '2007/01/02', '[22]')
DEBUG: SELECT nextval('tbltest_oid_seq')
DEBUG: INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '09:00:23', 'NOANSWER', '[123456789]', '[X2]', '[CPE]', 2057, '[01]', '2007/01/02', '[61]')
DEBUG: SELECT nextval('tbltest_oid_seq')
ERROR: DB error , [SELECT nextval('tbltest_oid_seq')]
ERROR: /home/rthompso/src/repo.nitroproject.org/script/../og/lib/og/adapter/postgresql.rb:125:in `query_statement'
/home/rthompso/src/repo.nitroproject.org/script/../og/lib/og/store/sql.rb:556:in `query'
/home/rthompso/src/repo.nitroproject.org/script/../og/lib/og/adapter/postgresql.rb:156:in `insert'
/home/rthompso/src/repo.nitroproject.org/script/../og/lib/og/store/sql.rb:102:in `og_insert'
/home/rthompso/src/repo.nitroproject.org/script/../og/lib/og/store.rb:94:in `save'
/home/rthompso/src/repo.nitroproject.org/script/../og/lib/og/model.rb:22:in `save'
/home/rthompso/src/repo.nitroproject.org/script/../og/lib/og/manager.rb:113:in `with_store'
/home/rthompso/src/repo.nitroproject.org/script/../og/lib/og/model.rb:21:in `save'
tbl.rb:50
tbl.rb:36:in `each_line'
tbl.rb:36
/home/rthompso/src/repo.nitroproject.org/script/../og/lib/og/store.rb:205:in `transaction'
/home/rthompso/src/repo.nitroproject.org/script/../og/lib/og/model.rb:490:in `transaction'
/home/rthompso/src/repo.nitroproject.org/script/../og/lib/og/manager.rb:113:in `with_store'
/home/rthompso/src/repo.nitroproject.org/script/../og/lib/og/model.rb:489:in `transaction'
tbl.rb:35
DEBUG: ROLLBACK
DEBUG: Og::StoreException: Og::StoreException
DEBUG: /home/rthompso/src/repo.nitroproject.org/script/../og/lib/og/store/sql.rb:595:in `handle_sql_exception'
DEBUG: /home/rthompso/src/repo.nitroproject.org/script/../og/lib/og/store/sql.rb:559:in `query'
DEBUG: /home/rthompso/src/repo.nitroproject.org/script/../og/lib/og/adapter/postgresql.rb:156:in `insert'
DEBUG: /home/rthompso/src/repo.nitroproject.org/script/../og/lib/og/store/sql.rb:102:in `og_insert'
DEBUG: /home/rthompso/src/repo.nitroproject.org/script/../og/lib/og/store.rb:94:in `save'
DEBUG: /home/rthompso/src/repo.nitroproject.org/script/../og/lib/og/model.rb:22:in `save'
DEBUG: /home/rthompso/src/repo.nitroproject.org/script/../og/lib/og/manager.rb:113:in `with_store'
DEBUG: /home/rthompso/src/repo.nitroproject.org/script/../og/lib/og/model.rb:21:in `save'
DEBUG: tbl.rb:50
DEBUG: tbl.rb:36:in `each_line'
DEBUG: tbl.rb:36
DEBUG: /home/rthompso/src/repo.nitroproject.org/script/../og/lib/og/store.rb:205:in `transaction'
DEBUG: /home/rthompso/src/repo.nitroproject.org/script/../og/lib/og/model.rb:490:in `transaction'
DEBUG: /home/rthompso/src/repo.nitroproject.org/script/../og/lib/og/manager.rb:113:in `with_store'
DEBUG: /home/rthompso/src/repo.nitroproject.org/script/../og/lib/og/model.rb:489:in `transaction'
DEBUG: tbl.rb:35

So according to DBG, we started a transaction, did some inserts, I
CTRL-C'd the script, we did a ROLLBACK.
Per documentation, I should not have been able to read any of the data
prior to the commit,, yet selects show data as it is being entered.
Also, after the ROLLBACK, all data is still in the table.

postgresql log shows...
2007-06-05 08:27:12 EDT LOG:  statement: BEGIN TRANSACTION
2007-06-05 08:27:12 EDT LOG:  statement: SELECT nextval('tbltest_oid_seq')
2007-06-05 08:27:12 EDT LOG:  statement: INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '08:00:53', 'BUSY', '[9544250950]', '[SE]', '[566]', 1, '[01]', '2007/01/02', '[62]')
2007-06-05 08:27:12 EDT LOG:  statement: INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '08:00:53', 'SITTONE', '[123456789]', '[SE]', '[569]', 2, '[01]', '2007/01/02', '[48]')
2007-06-05 08:27:12 EDT LOG:  statement: INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '08:00:54', 'BUSY', '[123456789]', '[SE]', '[566]', 3, '[01]', '2007/01/02', '[62]')
2007-06-05 08:27:12 EDT LOG:  statement: INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '08:00:57', 'BUSY', '[123456789]', '[SE]', '[566]', 4, '[01]', '2007/01/02', '[62]')
2007-06-05 08:27:12 EDT LOG:  statement: INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '08:00:57', 'SITTONE', '[123456789]', '[SE]', '[566]', 5, '[01]', '2007/01/02', '[48]')
2007-06-05 08:27:12 EDT LOG:  statement: INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '08:00:58', 'BUSY', '[123456789]', '[SF]', '[566]', 6, '[01]', '2007/01/02', '[62]')
2007-06-05 08:27:12 EDT LOG:  statement: INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '08:00:58', 'BUSY', '[123456789]', '[SE]', '[566]', 7, '[01]', '2007/01/02', '[62]')
2007-06-05 08:27:12 EDT LOG:  statement: INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '08:01:05', 'SITTONE', '[123456789]', '[SF]', '[566]', 8, '[01]', '2007/01/02', '[48]')
2007-06-05 08:27:12 EDT LOG:  statement: INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '08:01:06', 'SITTONE', '[123456789]', '[SE]', '[566]', 9, '[01]', '2007/01/02', '[48]')
2007-06-05 08:27:12 EDT LOG:  statement: INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '08:01:07', 'SITTONE', '[123456789]', '[SE]', '[566]', 10, '[01]', '2007/01/02', '[48]')
...
...
2007-06-05 08:27:26 EDT LOG:  statement: INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '09:00:21', 'ANSM_LEFTMSG', '[123456789]', '[X2]', '[CPE]', 2056, '[01]', '2007/01/02', '[22]')
2007-06-05 08:27:26 EDT LOG:  statement: SELECT nextval('tbltest_oid_seq')
2007-06-05 08:27:26 EDT LOG:  statement: INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '09:00:23', 'NOANSWER', '[123456789]', '[X2]', '[CPE]', 2057, '[01]', '2007/01/02', '[61]')
2007-06-05 08:27:26 EDT LOG:  statement: SELECT nextval('tbltest_oid_seq')
2007-06-05 08:27:26 EDT LOG:  statement: ROLLBACK


If I take the postgresql log output and remove the extraneous log info,
and feed it to psql ala psql -U rthompso -f /tmp/test tbl, then selects
return empty while it is loading, and the rollback leaves the table
empty -- I.E. it works as expected...

test file....
BEGIN TRANSACTION;
INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '08:00:53', 'BUSY', '[123456789]', '[SE]', '[566]', 1, '[01]', '2007/01/02', '[62]');
INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '08:00:53', 'SITTONE', '[123456789]', '[SE]', '[569]', 2, '[01]', '2007/01/02', '[48]');
INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '08:00:54', 'BUSY', '[123456789]', '[SE]', '[566]', 3, '[01]', '2007/01/02', '[62]');
INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '08:00:57', 'BUSY', '[123456789]', '[SE]', '[566]', 4, '[01]', '2007/01/02', '[62]');
INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '08:00:57', 'SITTONE', '[123456789]', '[SE]', '[566]', 5, '[01]', '2007/01/02', '[48]');
INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '08:00:58', 'BUSY', '[123456789]', '[SF]', '[566]', 6, '[01]', '2007/01/02', '[62]');
INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '08:00:58', 'BUSY', '[123456789]', '[SE]', '[566]', 7, '[01]', '2007/01/02', '[62]');
INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '08:01:05', 'SITTONE', '[123456789]', '[SF]', '[566]', 8, '[01]', '2007/01/02', '[48]');
INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '08:01:06', 'SITTONE', '[123456789]', '[SE]', '[566]', 9, '[01]', '2007/01/02', '[48]');
INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '08:01:07', 'SITTONE', '[123456789]', '[SE]', '[566]', 10, '[01]', '2007/01/02', '[48]');
...
...

INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '09:00:20', 'ANSM_LEFTMSG', '[123456789]', '[X2]', '[CPE]', 2055, '[01]', '2007/01/02', '[22]');
INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '09:00:21', 'ANSM_LEFTMSG', '[123456789]', '[X2]', '[CPE]', 2056, '[01]', '2007/01/02', '[22]');
INSERT INTO tbltest ("type", "ts", "result", "telno", "location", "calltype", "oid", "fa", "date", "fn") VALUES ('CALL:TN', '09:00:23', 'NOANSWER', '[123456789]', '[X2]', '[CPE]', 2057, '[01]', '2007/01/02', '[61]');
ROLLBACK;




More information about the Nitro-general mailing list