Thread: 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@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@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
On 07/10/2012 01:06 PM, Jeff Ross wrote: > 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. > > 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! For your initial attempt everything was done in one session? I am also confused by this: 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 Note the time stamps. Is this the actual log? > > Jeff Ross > Wyoming Children's Action Alliance > -- Adrian Klaver adrian.klaver@gmail.com
On 7/10/12 6:21 PM, Adrian Klaver wrote: > On 07/10/2012 01:06 PM, Jeff Ross wrote: >> 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. > >> >> 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! > > For your initial attempt everything was done in one session? All the inserts were done in one session, yes. > > I am also confused by this: > 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 > > Note the time stamps. Is this the actual log? Crap. I noticed that I'd somehow got another update statement when I pasted into the e-mail so I altered the srv_resp_pp_id to match rather than go get the real entry from the logs again. That is for sure my bad and I apologize! The sequence of events are as I described, though. The inserts happen inside a transaction, the update happens immediately after the commit. Jeff > >> >> Jeff Ross >> Wyoming Children's Action Alliance >> > >
On 07/10/2012 07:30 PM, Jeff Ross wrote: > On 7/10/12 6:21 PM, Adrian Klaver wrote: >> On 07/10/2012 01:06 PM, Jeff Ross wrote: >>> Hi all, >>> >>> >>> Thanks for any and all ideas! >> >> For your initial attempt everything was done in one session? > > All the inserts were done in one session, yes. >> >> I am also confused by this: >> 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 >> >> Note the time stamps. Is this the actual log? > > Crap. I noticed that I'd somehow got another update statement when I > pasted into the e-mail so I altered the srv_resp_pp_id to match rather > than go get the real entry from the logs again. That is for sure my bad > and I apologize! The sequence of events are as I described, though. The > inserts happen inside a transaction, the update happens immediately > after the commit. So would it be possible to see the actual log sequence? > > Jeff >> >>> >>> Jeff Ross >>> Wyoming Children's Action Alliance -- Adrian Klaver adrian.klaver@gmail.com
On 7/10/12 8:39 PM, Adrian Klaver wrote:
> On 07/10/2012 07:30 PM, Jeff Ross wrote:
>> On 7/10/12 6:21 PM, Adrian Klaver wrote:
>>> On 07/10/2012 01:06 PM, Jeff Ross wrote:
>>>> Hi all,
>>>>
>
>>>>
>>>> Thanks for any and all ideas!
>>>
>>> For your initial attempt everything was done in one session?
>>
>> All the inserts were done in one session, yes.
>>>
>>> I am also confused by this:
>>> 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
>>>
>>> Note the time stamps. Is this the actual log?
>>
>> Crap. I noticed that I'd somehow got another update statement when I
>> pasted into the e-mail so I altered the srv_resp_pp_id to match rather
>> than go get the real entry from the logs again. That is for sure my bad
>> and I apologize! The sequence of events are as I described, though. The
>> inserts happen inside a transaction, the update happens immediately
>> after the commit.
>
> So would it be possible to see the actual log sequence?
>
Absolutely.
2012-06-19 15:37:36.149840500 <www%wykids> LOG: statement: SET
DATESTYLE TO SQL, MDY
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:37:36.283752500 <www%wykids> LOG: statement: update
survey_response set srv_resp_submitted = now() where srv_resp_srv_id = 2
and srv_resp_pp_id = 25399
Thanks!
>>>>
>>>> Jeff Ross
>>>> Wyoming Children's Action Alliance
>
>
>
On 07/11/2012 07:01 AM, Jeff Ross wrote:
> On 7/10/12 8:39 PM, Adrian Klaver wrote:
>> On 07/10/2012 07:30 PM, Jeff Ross wrote:
>>> On 7/10/12 6:21 PM, Adrian Klaver wrote:
>>>> On 07/10/2012 01:06 PM, Jeff Ross wrote:
>>>>> Hi all,
>>>>>
>>
>>>>>
>>>>> Thanks for any and all ideas!
>>>>
>>>> For your initial attempt everything was done in one session?
>>>
>>> All the inserts were done in one session, yes.
>>
>> So would it be possible to see the actual log sequence?
>>
> Absolutely.
>
> 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:37:36.283752500 <www%wykids> LOG: statement: update
> survey_response set srv_resp_submitted = now() where srv_resp_srv_id = 2
> and srv_resp_pp_id = 25399
Hmm, nothing stands out. Some bottom of the bag ideas:
1) Is there more than one survey_answers table in the database, in
different schema?
2) When you are looking for the survey answers in the table are you
connecting to the parent or child database in the replication setup?
>
> Thanks!
>
>>>>>
>>>>> Jeff Ross
>>>>> Wyoming Children's Action Alliance
>>
>>
>>
>
>
--
Adrian Klaver
adrian.klaver@gmail.com
On 07/11/2012 07:01 AM, Jeff Ross wrote: > On 7/10/12 8:39 PM, Adrian Klaver wrote: >> On 07/10/2012 07:30 PM, Jeff Ross wrote: >>> On 7/10/12 6:21 PM, Adrian Klaver wrote: >>>> On 07/10/2012 01:06 PM, Jeff Ross wrote: >>>>> Hi all, >>>>> >> >>>>> >>>>> Thanks for any and all ideas! >>>> >> >> So would it be possible to see the actual log sequence? >> > Absolutely. > Thanks! To add to my previous post, are there any INSERT triggers on the tables involved? > >>>>> >>>>> Jeff Ross >>>>> Wyoming Children's Action Alliance >> >> >> > > -- Adrian Klaver adrian.klaver@gmail.com
On 7/11/12 2:07 PM, Adrian Klaver wrote:
> On 07/11/2012 07:01 AM, Jeff Ross wrote:
>> On 7/10/12 8:39 PM, Adrian Klaver wrote:
>>> On 07/10/2012 07:30 PM, Jeff Ross wrote:
>>>> On 7/10/12 6:21 PM, Adrian Klaver wrote:
>>>>> On 07/10/2012 01:06 PM, Jeff Ross wrote:
>>>>>> Hi all,
>>>>>>
>>>
>>>>>>
>>>>>> Thanks for any and all ideas!
>>>>>
>>>>> For your initial attempt everything was done in one session?
>>>>
>>>> All the inserts were done in one session, yes.
>
>>>
>>> So would it be possible to see the actual log sequence?
>>>
>> Absolutely.
>>
>
>> 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:37:36.283752500 <www%wykids> LOG: statement: update
>> survey_response set srv_resp_submitted = now() where srv_resp_srv_id = 2
>> and srv_resp_pp_id = 25399
>
> Hmm, nothing stands out. Some bottom of the bag ideas:
>
> 1) Is there more than one survey_answers table in the database, in
> different schema?
No, just the public schema in this database.
>
> 2) When you are looking for the survey answers in the table are you
> connecting to the parent or child database in the replication setup?
>
Parent.
In answer to your next question, no, there are no insert triggers.
After finding this I looked at the other 2 surveys we've done and found
similar anomalies in each, Each of those surveys have had 250 or so
respondents. In the first, 2 records were updated with a submit time,
but with no corresponding inserts in survey_answers, in the second it
was 3. The first survey was done at the end of last year and the logs
have rotated out for those transactions. The second survey is yet
ongoing so I was able to do the same fix as before.
My worry is that if these transactions are failing silently, if indeed
that is what is happening, how many other transactions to other tables
are also silently failing? This proved relatively easy to find because
the update statement was outside the transaction and when the number of
people with submitted entries did not match the number of people with
answers in survey_answers I started digging. Most of the time, though, I
trust transactions to either succeed or fail obviously with an error.
Jeff
>>
>> Thanks!
>>
>>>>>>
>>>>>> Jeff Ross
>>>>>> Wyoming Children's Action Alliance
>>>
>>>
>>>
>>
>>
>
>
On 07/11/2012 02:41 PM, Jeff Ross wrote:
> On 7/11/12 2:07 PM, Adrian Klaver wrote:
>> On 07/11/2012 07:01 AM, Jeff Ross wrote:
>>> On 7/10/12 8:39 PM, Adrian Klaver wrote:
>>>> On 07/10/2012 07:30 PM, Jeff Ross wrote:
>>>>> On 7/10/12 6:21 PM, Adrian Klaver wrote:
>>>>>> On 07/10/2012 01:06 PM, Jeff Ross wrote:
>>>>>>> Hi all,
>>>>>>>
>>>>
>>>>>>>
>>>>>>> Thanks for any and all ideas!
>>>>>>
>>>>>> For your initial attempt everything was done in one session?
>>>>>
>>>>> All the inserts were done in one session, yes.
>>
>>>>
>>>> So would it be possible to see the actual log sequence?
>>>>
>>> Absolutely.
>>>
>>
>>> 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:37:36.283752500 <www%wykids> LOG: statement: update
>>> survey_response set srv_resp_submitted = now() where srv_resp_srv_id = 2
>>> and srv_resp_pp_id = 25399
>>
>> Hmm, nothing stands out. Some bottom of the bag ideas:
>>
>> 1) Is there more than one survey_answers table in the database, in
>> different schema?
>
> No, just the public schema in this database.
>>
>> 2) When you are looking for the survey answers in the table are you
>> connecting to the parent or child database in the replication setup?
>>
>
> Parent.
>
> In answer to your next question, no, there are no insert triggers.
>
> After finding this I looked at the other 2 surveys we've done and found
> similar anomalies in each, Each of those surveys have had 250 or so
> respondents. In the first, 2 records were updated with a submit time,
> but with no corresponding inserts in survey_answers, in the second it
> was 3. The first survey was done at the end of last year and the logs
> have rotated out for those transactions. The second survey is yet
> ongoing so I was able to do the same fix as before.
>
> My worry is that if these transactions are failing silently, if indeed
> that is what is happening, how many other transactions to other tables
> are also silently failing? This proved relatively easy to find because
> the update statement was outside the transaction and when the number of
> people with submitted entries did not match the number of people with
> answers in survey_answers I started digging. Most of the time, though, I
> trust transactions to either succeed or fail obviously with an error.
Is there an index on this table?
If so have you tried a REINDEX?
>
> Jeff
>>>
>>> Thanks!
>>>
>>>>>>>
>>>>>>> Jeff Ross
>>>>>>> Wyoming Children's Action Alliance
>>>>
>>>>
>>>>
>>>
>>>
>>
>>
>
>
>
>
--
Adrian Klaver
adrian.klaver@gmail.com
On Tue, Jul 10, 2012 at 10:06 PM, Jeff Ross <jross@wykids.org> wrote:
2012-06-19 15:37:36.283752500 <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@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
-------------+-----------------+----------------+----------------------------+----------------------------+----------------------------
5674 | 2 | 25399 | 2012-06-19 15:12:49.589233 | 2012-06-19 15:33:05.547012 | 2012-06-19 15:38:16.724393
The timestamps don't match - something updated the record after 15:37:36 .
Also, are the fields like srv_answers_srv_id character fields? The inserts are quoting them like varchars, which seems odd.
Greetings
Marcin
On 7/11/12 3:52 PM, Adrian Klaver wrote:
> On 07/11/2012 02:41 PM, Jeff Ross wrote:
>> On 7/11/12 2:07 PM, Adrian Klaver wrote:
>>> On 07/11/2012 07:01 AM, Jeff Ross wrote:
>>>> On 7/10/12 8:39 PM, Adrian Klaver wrote:
>>>>> On 07/10/2012 07:30 PM, Jeff Ross wrote:
>>>>>> On 7/10/12 6:21 PM, Adrian Klaver wrote:
>>>>>>> On 07/10/2012 01:06 PM, Jeff Ross wrote:
>>>>>>>> Hi all,
>>>>>>>>
>>>>>
>>>>>>>>
>>>>>>>> Thanks for any and all ideas!
>>>>>>>
>>>>>>> For your initial attempt everything was done in one session?
>>>>>>
>>>>>> All the inserts were done in one session, yes.
>>>
>>>>>
>>>>> So would it be possible to see the actual log sequence?
>>>>>
>>>> Absolutely.
>>>>
>>>
>>>> 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:37:36.283752500 <www%wykids> LOG: statement: update
>>>> survey_response set srv_resp_submitted = now() where
>>>> srv_resp_srv_id = 2
>>>> and srv_resp_pp_id = 25399
>>>
>>> Hmm, nothing stands out. Some bottom of the bag ideas:
>>>
>>> 1) Is there more than one survey_answers table in the database, in
>>> different schema?
>>
>> No, just the public schema in this database.
>>>
>>> 2) When you are looking for the survey answers in the table are you
>>> connecting to the parent or child database in the replication setup?
>>>
>>
>> Parent.
>>
>> In answer to your next question, no, there are no insert triggers.
>>
>> After finding this I looked at the other 2 surveys we've done and found
>> similar anomalies in each, Each of those surveys have had 250 or so
>> respondents. In the first, 2 records were updated with a submit time,
>> but with no corresponding inserts in survey_answers, in the second it
>> was 3. The first survey was done at the end of last year and the logs
>> have rotated out for those transactions. The second survey is yet
>> ongoing so I was able to do the same fix as before.
>>
>> My worry is that if these transactions are failing silently, if indeed
>> that is what is happening, how many other transactions to other tables
>> are also silently failing? This proved relatively easy to find because
>> the update statement was outside the transaction and when the number of
>> people with submitted entries did not match the number of people with
>> answers in survey_answers I started digging. Most of the time, though, I
>> trust transactions to either succeed or fail obviously with an error.
>
> Is there an index on this table?
> If so have you tried a REINDEX?
>
Here's the table definition:
jross@nirvana:/home/jross $ psql wykids
psql (9.1.4, server 9.1.3)
Type "help" for help.
wykids=# \d survey_answers
Table "public.survey_answers"
Column | Type | Modifiers
-----------------------------+---------+-------------------------------------------------------------------------
srv_answers_id | integer | not null default
nextval('survey_answers_srv_answers_id_seq'::regclass)
srv_answers_srv_id | integer | not null
srv_answers_pp_id | integer | not null
srv_answers_question_id | integer | not null
srv_answers_answer | integer |
srv_answers_answer_text | text |
srv_answers_rank | integer |
srv_answers_sub_question_id | integer |
Indexes:
"survey_answers_pkey" PRIMARY KEY, btree (srv_answers_id)
Foreign-key constraints:
"survey_answers_srv_answers_answer_fkey" FOREIGN KEY
(srv_answers_answer) REFERENCES survey_possible_answers(srv_pos_answers_id)
"survey_answers_srv_answers_pp_id_fkey" FOREIGN KEY
(srv_answers_pp_id) REFERENCES people(pp_id)
"survey_answers_srv_answers_question_id_fkey" FOREIGN KEY
(srv_answers_question_id) REFERENCES survey_questions(srv_question_id)
"survey_answers_srv_answers_srv_id_fkey" FOREIGN KEY
(srv_answers_srv_id) REFERENCES surveys(srv_id)
wykids=#
I haven't re-indexed that table but somehow I find it hard to believe
that a reindex can make those rows appear. I just tried it on my
development server--no change.
Jeff
>>
>> Jeff
>>>>
>>>> Thanks!
>>>>
>>>>>>>>
>>>>>>>> Jeff Ross
>>>>>>>> Wyoming Children's Action Alliance
>>>>>
>>>>>
>>>>>
>>>>
>>>>
>>>
>>>
>>
>>
>>
>>
>
>
On 7/11/12 4:24 PM, Marcin Mańk wrote:
Yes, that was a copy / paste error that I tried to fix rather than re-do. I explained that up thread.On Tue, Jul 10, 2012 at 10:06 PM, Jeff Ross <jross@wykids.org> wrote:!DSPAM:4ffdfd2b110892010192983!2012-06-19 15:37:36.283752500 <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@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
-------------+-----------------+----------------+----------------------------+----------------------------+----------------------------
5674 | 2 | 25399 | 2012-06-19 15:12:49.589233 | 2012-06-19 15:33:05.547012 | 2012-06-19 15:38:16.724393The timestamps don't match - something updated the record after 15:37:36 .Also, are the fields like srv_answers_srv_id character fields? The inserts are quoting them like varchars, which seems odd.GreetingsMarcin
I just posted the table definition but they are integer fields. As far as the quoting of integer fields, that is the way Pear DB does inserts. What's the harm?
Jeff
On 07/11/2012 04:02 PM, Jeff Ross wrote:
> On 7/11/12 3:52 PM, Adrian Klaver wrote:
>>
>> Is there an index on this table?
>> If so have you tried a REINDEX?
>>
>
> Here's the table definition:
>
> jross@nirvana:/home/jross $ psql wykids
> psql (9.1.4, server 9.1.3)
> Type "help" for help.
>
> wykids=# \d survey_answers
> Table "public.survey_answers"
> Column | Type | Modifiers
> -----------------------------+---------+-------------------------------------------------------------------------
>
> srv_answers_id | integer | not null default
> nextval('survey_answers_srv_answers_id_seq'::regclass)
> srv_answers_srv_id | integer | not null
> srv_answers_pp_id | integer | not null
> srv_answers_question_id | integer | not null
> srv_answers_answer | integer |
> srv_answers_answer_text | text |
> srv_answers_rank | integer |
> srv_answers_sub_question_id | integer |
> Indexes:
> "survey_answers_pkey" PRIMARY KEY, btree (srv_answers_id)
> Foreign-key constraints:
> "survey_answers_srv_answers_answer_fkey" FOREIGN KEY
> (srv_answers_answer) REFERENCES survey_possible_answers(srv_pos_answers_id)
> "survey_answers_srv_answers_pp_id_fkey" FOREIGN KEY
> (srv_answers_pp_id) REFERENCES people(pp_id)
> "survey_answers_srv_answers_question_id_fkey" FOREIGN KEY
> (srv_answers_question_id) REFERENCES survey_questions(srv_question_id)
> "survey_answers_srv_answers_srv_id_fkey" FOREIGN KEY
> (srv_answers_srv_id) REFERENCES surveys(srv_id)
>
> wykids=#
>
> I haven't re-indexed that table but somehow I find it hard to believe
> that a reindex can make those rows appear. I just tried it on my
> development server--no change.
The development server has the same issue with missing records?
>
> Jeff
>
--
Adrian Klaver
adrian.klaver@gmail.com
On 7/11/12 5:13 PM, Adrian Klaver wrote:
> On 07/11/2012 04:02 PM, Jeff Ross wrote:
>> On 7/11/12 3:52 PM, Adrian Klaver wrote:
>
>>>
>>> Is there an index on this table?
>>> If so have you tried a REINDEX?
>>>
>>
>> Here's the table definition:
>>
>> jross@nirvana:/home/jross $ psql wykids
>> psql (9.1.4, server 9.1.3)
>> Type "help" for help.
>>
>> wykids=# \d survey_answers
>> Table "public.survey_answers"
>> Column | Type | Modifiers
>> -----------------------------+---------+-------------------------------------------------------------------------
>>
>>
>> srv_answers_id | integer | not null default
>> nextval('survey_answers_srv_answers_id_seq'::regclass)
>> srv_answers_srv_id | integer | not null
>> srv_answers_pp_id | integer | not null
>> srv_answers_question_id | integer | not null
>> srv_answers_answer | integer |
>> srv_answers_answer_text | text |
>> srv_answers_rank | integer |
>> srv_answers_sub_question_id | integer |
>> Indexes:
>> "survey_answers_pkey" PRIMARY KEY, btree (srv_answers_id)
>> Foreign-key constraints:
>> "survey_answers_srv_answers_answer_fkey" FOREIGN KEY
>> (srv_answers_answer) REFERENCES
>> survey_possible_answers(srv_pos_answers_id)
>> "survey_answers_srv_answers_pp_id_fkey" FOREIGN KEY
>> (srv_answers_pp_id) REFERENCES people(pp_id)
>> "survey_answers_srv_answers_question_id_fkey" FOREIGN KEY
>> (srv_answers_question_id) REFERENCES survey_questions(srv_question_id)
>> "survey_answers_srv_answers_srv_id_fkey" FOREIGN KEY
>> (srv_answers_srv_id) REFERENCES surveys(srv_id)
>>
>> wykids=#
>>
>> I haven't re-indexed that table but somehow I find it hard to believe
>> that a reindex can make those rows appear. I just tried it on my
>> development server--no change.
>
> The development server has the same issue with missing records?
Yes, but it is db dropped and reloaded daily from the real server so
that is to be expected.
>
>>
>> Jeff
>
>>
>
>
On 07/11/2012 04:18 PM, Jeff Ross wrote:
> On 7/11/12 5:13 PM, Adrian Klaver wrote:
>> On 07/11/2012 04:02 PM, Jeff Ross wrote:
>>> On 7/11/12 3:52 PM, Adrian Klaver wrote:
>>
>>>>
>>>> Is there an index on this table?
>>>> If so have you tried a REINDEX?
>>>>
>>>
>>> Here's the table definition:
>>>
>>> jross@nirvana:/home/jross $ psql wykids
>>> psql (9.1.4, server 9.1.3)
>>> Type "help" for help.
>>>
>>> wykids=# \d survey_answers
>>> Table "public.survey_answers"
>>> Column | Type | Modifiers
>>> -----------------------------+---------+-------------------------------------------------------------------------
>>>
>>>
>>> srv_answers_id | integer | not null default
>>> nextval('survey_answers_srv_answers_id_seq'::regclass)
>>> srv_answers_srv_id | integer | not null
>>> srv_answers_pp_id | integer | not null
>>> srv_answers_question_id | integer | not null
>>> srv_answers_answer | integer |
>>> srv_answers_answer_text | text |
>>> srv_answers_rank | integer |
>>> srv_answers_sub_question_id | integer |
>>> Indexes:
>>> "survey_answers_pkey" PRIMARY KEY, btree (srv_answers_id)
>>> Foreign-key constraints:
>>> "survey_answers_srv_answers_answer_fkey" FOREIGN KEY
>>> (srv_answers_answer) REFERENCES
>>> survey_possible_answers(srv_pos_answers_id)
>>> "survey_answers_srv_answers_pp_id_fkey" FOREIGN KEY
>>> (srv_answers_pp_id) REFERENCES people(pp_id)
>>> "survey_answers_srv_answers_question_id_fkey" FOREIGN KEY
>>> (srv_answers_question_id) REFERENCES survey_questions(srv_question_id)
>>> "survey_answers_srv_answers_srv_id_fkey" FOREIGN KEY
>>> (srv_answers_srv_id) REFERENCES surveys(srv_id)
>>>
>>> wykids=#
>>>
>>> I haven't re-indexed that table but somehow I find it hard to believe
>>> that a reindex can make those rows appear. I just tried it on my
>>> development server--no change.
To answer the above, see below. Not saying this is what happened in your
case, but it can happen.
http://www.postgresql.org/docs/9.1/static/release-9-1-3.html
Fix btree index corruption from insertions concurrent with vacuuming
(Tom Lane)
An index page split caused by an insertion could sometimes cause a
concurrently-running VACUUM to miss removing index entries that it
should remove. After the corresponding table rows are removed, the
dangling index entries would cause errors (such as "could not read block
N in file ...") or worse, silently wrong query results after unrelated
rows are re-inserted at the now-free table locations. This bug has been
present since release 8.2, but occurs so infrequently that it was not
diagnosed until now. If you have reason to suspect that it has happened
in your database, reindexing the affected index will fix things.
>>
>> The development server has the same issue with missing records?
>
> Yes, but it is db dropped and reloaded daily from the real server so
> that is to be expected.
>>
>>>
>>> Jeff
>>
>>>
>>
>>
>
>
>
>
--
Adrian Klaver
adrian.klaver@gmail.com