Transaction question

Hi all,

I have an anomaly on my hands that I'm at a loss to understand.

We recently ran a small survey where participants were required to
answer all the questions. After validation for skipped questions,
mis-ranking answers that had to be ranked and so on, I did all of the
inserts to the survey_answers table inside a transaction block followed
by a commit. Immediately after, I updated the survey_response table
and set a timestamp to show the submitted time.

In 3 of the 38 responses, the logs show the inserts with no database
errors followed by the update statement, however, there are no entries
for that person in the survey_answers table. It is as if the
transaction rolled back, but if so, that fact is not in the logs.

Here are the log entries for one of the transaction blocks in question:

2012-06-19 15:37:36.150735500 <www%wykids> LOG: statement: create temp
table if not exists rank_test (value integer unique not null)
2012-06-19 15:37:36.201496500 <www%wykids> LOG: statement: truncate
rank_test
2012-06-19 15:37:36.218830500 <www%wykids> LOG: statement: insert into
rank_test values(5)
2012-06-19 15:37:36.220442500 <www%wykids> LOG: statement: insert into
rank_test values(4)
2012-06-19 15:37:36.221109500 <www%wykids> LOG: statement: insert into
rank_test values(3)
2012-06-19 15:37:36.221654500 <www%wykids> LOG: statement: insert into
rank_test values(2)
2012-06-19 15:37:36.222142500 <www%wykids> LOG: statement: insert into
rank_test values(1)
2012-06-19 15:37:36.222759500 <www%wykids> LOG: statement: begin
2012-06-19 15:37:36.223783500 <www%wykids> LOG: statement: INSERT INTO
survey_answers
(srv_answers_srv_id,srv_answers_pp_id,srv_answers_question_id,srv_answers_answer,srv_answers_answer_text,srv_answers_rank,srv_answers_sub_question_id)
VALUES ('2','25399','13',NULL,NULL,'5','1')
2012-06-19 15:37:36.232725500 <www%wykids> LOG: statement: INSERT INTO
survey_answers
(srv_answers_srv_id,srv_answers_pp_id,srv_answers_question_id,srv_answers_answer,srv_answers_answer_text,srv_answers_rank,srv_answers_sub_question_id)
VALUES ('2','25399','13',NULL,NULL,'4','2')
2012-06-19 15:37:36.234958500 <www%wykids> LOG: statement: INSERT INTO
survey_answers
(srv_answers_srv_id,srv_answers_pp_id,srv_answers_question_id,srv_answers_answer,srv_answers_answer_text,srv_answers_rank,srv_answers_sub_question_id)
VALUES ('2','25399','13',NULL,NULL,'3','3')
2012-06-19 15:37:36.237111500 <www%wykids> LOG: statement: INSERT INTO
survey_answers
(srv_answers_srv_id,srv_answers_pp_id,srv_answers_question_id,srv_answers_answer,srv_answers_answer_text,srv_answers_rank,srv_answers_sub_question_id)
VALUES ('2','25399','13',NULL,NULL,'2','4')
2012-06-19 15:37:36.239208500 <www%wykids> LOG: statement: INSERT INTO
survey_answers
(srv_answers_srv_id,srv_answers_pp_id,srv_answers_question_id,srv_answers_answer,srv_answers_answer_text,srv_answers_rank,srv_answers_sub_question_id)
VALUES ('2','25399','13',NULL,NULL,'1','5')
2012-06-19 15:37:36.241350500 <www%wykids> LOG: statement: INSERT INTO
survey_answers
(srv_answers_srv_id,srv_answers_pp_id,srv_answers_question_id,srv_answers_answer,srv_answers_answer_text,srv_answers_rank,srv_answers_sub_question_id)
VALUES ('2','25399','15','4',NULL,NULL,NULL)
2012-06-19 15:37:36.244361500 <www%wykids> LOG: statement: INSERT INTO
survey_answers
(srv_answers_srv_id,srv_answers_pp_id,srv_answers_question_id,srv_answers_answer,srv_answers_answer_text,srv_answers_rank,srv_answers_sub_question_id)
VALUES ('2','25399','16',NULL,'Difficult behaviors',NULL,'1')
2012-06-19 15:37:36.246509500 <www%wykids> LOG: statement: INSERT INTO
survey_answers
(srv_answers_srv_id,srv_answers_pp_id,srv_answers_question_id,srv_answers_answer,srv_answers_answer_text,srv_answers_rank,srv_answers_sub_question_id)
VALUES ('2','25399','16',NULL,'Collecting from parents',NULL,'2')
2012-06-19 15:37:36.248644500 <www%wykids> LOG: statement: INSERT INTO
survey_answers
(srv_answers_srv_id,srv_answers_pp_id,srv_answers_question_id,srv_answers_answer,srv_answers_answer_text,srv_answers_rank,srv_answers_sub_question_id)
VALUES ('2','25399','16',NULL,'How to still have a life outside child
care.',NULL,'3')
2012-06-19 15:37:36.250742500 <www%wykids> LOG: statement: INSERT INTO
survey_answers
(srv_answers_srv_id,srv_answers_pp_id,srv_answers_question_id,srv_answers_answer,srv_answers_answer_text,srv_answers_rank,srv_answers_sub_question_id)
VALUES ('2','25399','17','1',NULL,NULL,NULL)
2012-06-19 15:37:36.252916500 <www%wykids> LOG: statement: INSERT INTO
survey_answers
(srv_answers_srv_id,srv_answers_pp_id,srv_answers_question_id,srv_answers_answer,srv_answers_answer_text,srv_answers_rank,srv_answers_sub_question_id)
VALUES ('2','25399','18','1',NULL,NULL,NULL)
2012-06-19 15:37:36.255100500 <www%wykids> LOG: statement: INSERT INTO
survey_answers
(srv_answers_srv_id,srv_answers_pp_id,srv_answers_question_id,srv_answers_answer,srv_answers_answer_text,srv_answers_rank,srv_answers_sub_question_id)
VALUES ('2','25399','19','1',NULL,NULL,NULL)
2012-06-19 15:37:36.257256500 <www%wykids> LOG: statement: INSERT INTO
survey_answers
(srv_answers_srv_id,srv_answers_pp_id,srv_answers_question_id,srv_answers_answer,srv_answers_answer_text,srv_answers_rank,srv_answers_sub_question_id)
VALUES ('2','25399','20','1',NULL,NULL,NULL)
2012-06-19 15:37:36.258912500 <www%wykids> LOG: statement: commit
2012-06-19 15:29:11.573396500 <www%wykids> LOG: statement: update
survey_response set srv_resp_submitted = now() where srv_resp_srv_id = 2
and srv_resp_pp_id = 25399

jross(at)wykids localhost# select * from survey_answers where
srv_answers_pp_id = 25399;
srv_answers_id | srv_answers_srv_id | srv_answers_pp_id |
srv_answers_question_id | srv_answers_answer | srv_answers_answer_text |
srv_answers_rank | srv_answers_sub_question_id
----------------+--------------------+-------------------+-------------------------+--------------------+-------------------------+------------------+-----------------------------
(0 rows)

In each of the three, the person's survey_response record was correctly
updated with the current_timestamp.

jross(at)wykids localhost# select * from survey_response where
srv_resp_submitted is not null and srv_resp_srv_id = 2 and
srv_resp_pp_id not in (select srv_answers_pp_id from survey_answers
where srv_answers_srv_id = 2);
srv_resp_id | srv_resp_srv_id | srv_resp_pp_id | srv_resp_invite
| srv_resp_first_look | srv_resp_submitted
-------------+-----------------+----------------+----------------------------+----------------------------+----------------------------
5651 | 2 | 23934 | 2012-06-19
15:12:47.231795 | 2012-06-19 21:21:46.710908 | 2012-06-19 21:29:38.084093
5674 | 2 | 25399 | 2012-06-19
15:12:49.589233 | 2012-06-19 15:33:05.547012 | 2012-06-19 15:38:16.724393
5595 | 2 | 19361 | 2012-06-19
15:12:39.37469 | 2012-06-19 18:26:00.391711 | 2012-06-19 18:38:47.068152
(3 rows)

After finding these anomalies, I cut and pasted the insert statements
from the logs into a file and inserted them manually with psql -f. No
errors, so I can't see why the transaction should have rolled back, if
indeed that is what happened. Is it possible for a transaction to
silently fail?

This is 9.1.3 running on OpenBSD and on a BBU RAID 1 mirror. It is the
master in a hot-standy setup. Logging is set to "all". I have no
reason to believe (yet, anyway) that this is some sort of hardware
problem as I see no indication of that anywhere else.

Thanks for any and all ideas!

Jeff Ross
Wyoming Children's Action Alliance