SEO

Hello,

I am running 8.1.3, built from source, on RHEL4/x64.

I have a Web application that uses this database to sell products. We have
an order table and an order lines table with a one to many relationship
between them.

For the past few months I have had a strange problem where sometimes (about
2% of orders), the line item rows disappear. By disappear I mean that they
are committed to the database and then when I go to look at the order later,
there are no line items. The row in the 'order' table still exists, it is
just the line(s) that vanish.

As I started looking into this problem I assumed that it was a bug in my Web
application. I did some extensive testing and logging to no avail. I turned
up the logging on my Web app and I can see the INSERTs but I never saw any
DELETE statements though I can't find the child row(s) in the DB.

I've been perplexed for quite some time so a few days ago I turned on the
following PG logging:

log_statement = 'mod'

Today, I found an order that has this problem. Grepping my serverlog, I see
the following:

The line item is inserted:

serverlog:LOG: statement: INSERT INTO order_lines ("order_description",
"order_id", "updated_at", "band_name", "order_item", "product_id",
"line_source", "order_quantity", "extended_price", "unit_price",
"catalog_number", "created_at") VALUES('FW "Not My Pres" Trucker Hat',
16899, '2006-05-06 14:43:38', NULL, 'Baseball Cap ', 165, 'Merch', 1, NULL,
7.0, 94, '2006-05-06 14:43:38')

Then, I do a SELECT:

fw_production=# SELECT COUNT(*) FROM order_lines WHERE order_id = 16899;
count
-------
0

There was about 3 hours between when the line was inserted and when I went
to look for it. There is no DELETE in the serverlog for this row.

I can't figure out where this row went and why it disappeared! Is it getting
deleted some other way that wouldn't be logged? Am I missing something
rudimentary?

Any help is appreciated.

Hunter



---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match

Just to be sure....

Any error msg in log?

Maybe you can run this query in psql and see if it return any error msg

Best regards

Rodrigo

HH wrote:
> Hello,
>
> I am running 8.1.3, built from source, on RHEL4/x64.
>
> I have a Web application that uses this database to sell products. We have
> an order table and an order lines table with a one to many relationship
> between them.
>
> For the past few months I have had a strange problem where sometimes (about
> 2% of orders), the line item rows disappear. By disappear I mean that they
> are committed to the database and then when I go to look at the order later,
> there are no line items. The row in the 'order' table still exists, it is
> just the line(s) that vanish.
>
> As I started looking into this problem I assumed that it was a bug in my Web
> application. I did some extensive testing and logging to no avail. I turned
> up the logging on my Web app and I can see the INSERTs but I never saw any
> DELETE statements though I can't find the child row(s) in the DB.
>
> I've been perplexed for quite some time so a few days ago I turned on the
> following PG logging:
>
> log_statement = 'mod'
>
> Today, I found an order that has this problem. Grepping my serverlog, I see
> the following:
>
> The line item is inserted:
>
> serverlog:LOG: statement: INSERT INTO order_lines ("order_description",
> "order_id", "updated_at", "band_name", "order_item", "product_id",
> "line_source", "order_quantity", "extended_price", "unit_price",
> "catalog_number", "created_at") VALUES('FW "Not My Pres" Trucker Hat',
> 16899, '2006-05-06 14:43:38', NULL, 'Baseball Cap ', 165, 'Merch', 1, NULL,
> 7.0, 94, '2006-05-06 14:43:38')
>
> Then, I do a SELECT:
>
> fw_production=# SELECT COUNT(*) FROM order_lines WHERE order_id = 16899;
> count
> -------
> 0
>
> There was about 3 hours between when the line was inserted and when I went
> to look for it. There is no DELETE in the serverlog for this row.
>
> I can't figure out where this row went and why it disappeared! Is it getting
> deleted some other way that wouldn't be logged? Am I missing something
> rudimentary?
>
> Any help is appreciated.
>
> Hunter
>
>
>
> ---------------------------(end of broadcast)---------------------------
> TIP 9: In versions below 8.0, the planner will ignore your desire to
> choose an index scan if your joining column's datatypes do not
> match
>
>

---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings

Is there an chance the rows are being inserted in a transaction that
fails and rolls back? Maybe look at all the lines that were inserted
with that order, and try them manually in psql, character for character,
and see if an error pops up for any of the lines?

Terry Fielder
terry@greatgulfhomes.com
Associate Director Software Development and Deployment
Great Gulf Homes / Ashton Woods Homes
Fax: (416) 441-9085



Rodrigo Gonzalez wrote:
> Just to be sure....
>
> Any error msg in log?
>
> Maybe you can run this query in psql and see if it return any error msg
>
> Best regards
>
> Rodrigo
>
> HH wrote:
>> Hello,
>>
>> I am running 8.1.3, built from source, on RHEL4/x64.
>>
>> I have a Web application that uses this database to sell products. We
>> have
>> an order table and an order lines table with a one to many relationship
>> between them.
>>
>> For the past few months I have had a strange problem where sometimes
>> (about
>> 2% of orders), the line item rows disappear. By disappear I mean that
>> they
>> are committed to the database and then when I go to look at the order
>> later,
>> there are no line items. The row in the 'order' table still exists,
>> it is
>> just the line(s) that vanish.
>>
>> As I started looking into this problem I assumed that it was a bug in
>> my Web
>> application. I did some extensive testing and logging to no avail. I
>> turned
>> up the logging on my Web app and I can see the INSERTs but I never
>> saw any
>> DELETE statements though I can't find the child row(s) in the DB.
>>
>> I've been perplexed for quite some time so a few days ago I turned on
>> the
>> following PG logging:
>>
>> log_statement = 'mod'
>>
>> Today, I found an order that has this problem. Grepping my serverlog,
>> I see
>> the following:
>>
>> The line item is inserted:
>>
>> serverlog:LOG: statement: INSERT INTO order_lines ("order_description",
>> "order_id", "updated_at", "band_name", "order_item", "product_id",
>> "line_source", "order_quantity", "extended_price", "unit_price",
>> "catalog_number", "created_at") VALUES('FW "Not My Pres" Trucker Hat',
>> 16899, '2006-05-06 14:43:38', NULL, 'Baseball Cap ', 165, 'Merch', 1,
>> NULL,
>> 7.0, 94, '2006-05-06 14:43:38')
>>
>> Then, I do a SELECT:
>>
>> fw_production=# SELECT COUNT(*) FROM order_lines WHERE order_id = 16899;
>> count -------
>> 0
>>
>> There was about 3 hours between when the line was inserted and when I
>> went
>> to look for it. There is no DELETE in the serverlog for this row.
>>
>> I can't figure out where this row went and why it disappeared! Is it
>> getting
>> deleted some other way that wouldn't be logged? Am I missing something
>> rudimentary?
>>
>> Any help is appreciated.
>>
>> Hunter
>>
>>
>>
>> ---------------------------(end of broadcast)---------------------------
>> TIP 9: In versions below 8.0, the planner will ignore your desire to
>> choose an index scan if your joining column's datatypes do not
>> match
>>
>>
>
> ---------------------------(end of broadcast)---------------------------
> TIP 5: don't forget to increase your free space map settings
>

---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings

Thanks for replying.

The only logfile I have is the 'serverlog' file that I have. Looking at that
file, I don't see any indications that there was an error.

The INSERT does return successfully in psql.

Any other possibilities?

> From: Rodrigo Gonzalez <rjgonzale@gmail.com>
> Date: Sat, 06 May 2006 20:33:29 -0300
> To: HH <lists@lastonepicked.com>
> Cc: PostgreSQL <pgsql-general@postgresql.org>
> Subject: Re: [GENERAL] Can't Figure Out Where Rows Are Going
>
> Just to be sure....
>
> Any error msg in log?
>
> Maybe you can run this query in psql and see if it return any error msg
>
> Best regards
>
> Rodrigo
>
> HH wrote:
>> Hello,
>>
>> I am running 8.1.3, built from source, on RHEL4/x64.
>>
>> I have a Web application that uses this database to sell products. We have
>> an order table and an order lines table with a one to many relationship
>> between them.
>>
>> For the past few months I have had a strange problem where sometimes (about
>> 2% of orders), the line item rows disappear. By disappear I mean that they
>> are committed to the database and then when I go to look at the order later,
>> there are no line items. The row in the 'order' table still exists, it is
>> just the line(s) that vanish.
>>
>> As I started looking into this problem I assumed that it was a bug in my Web
>> application. I did some extensive testing and logging to no avail. I turned
>> up the logging on my Web app and I can see the INSERTs but I never saw any
>> DELETE statements though I can't find the child row(s) in the DB.
>>
>> I've been perplexed for quite some time so a few days ago I turned on the
>> following PG logging:
>>
>> log_statement = 'mod'
>>
>> Today, I found an order that has this problem. Grepping my serverlog, I see
>> the following:
>>
>> The line item is inserted:
>>
>> serverlog:LOG: statement: INSERT INTO order_lines ("order_description",
>> "order_id", "updated_at", "band_name", "order_item", "product_id",
>> "line_source", "order_quantity", "extended_price", "unit_price",
>> "catalog_number", "created_at") VALUES('FW "Not My Pres" Trucker Hat',
>> 16899, '2006-05-06 14:43:38', NULL, 'Baseball Cap ', 165, 'Merch', 1, NULL,
>> 7.0, 94, '2006-05-06 14:43:38')
>>
>> Then, I do a SELECT:
>>
>> fw_production=# SELECT COUNT(*) FROM order_lines WHERE order_id = 16899;
>> count
>> -------
>> 0
>>
>> There was about 3 hours between when the line was inserted and when I went
>> to look for it. There is no DELETE in the serverlog for this row.
>>
>> I can't figure out where this row went and why it disappeared! Is it getting
>> deleted some other way that wouldn't be logged? Am I missing something
>> rudimentary?
>>
>> Any help is appreciated.
>>
>> Hunter
>>
>>
>>
>> ---------------------------(end of broadcast)---------------------------
>> TIP 9: In versions below 8.0, the planner will ignore your desire to
>> choose an index scan if your joining column's datatypes do not
>> match
>>
>>



---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql.org so that your
message can get through to the mailing list cleanly

Thanks for taking the time to reply.

If that was occurring, would the log show it? I don't see any sign of a
roll-back occurring in the log and when I run the queries in psql, they seem
to complete properly.


> From: Terry Fielder <terry@ashtonwoodshomes.com>
> Date: Sat, 06 May 2006 19:43:19 -0400
> To: Rodrigo Gonzalez <rjgonzale@gmail.com>
> Cc: HH <lists@lastonepicked.com>, PostgreSQL <pgsql-general@postgresql.org>
> Subject: Re: [GENERAL] Can't Figure Out Where Rows Are Going
>
> Is there an chance the rows are being inserted in a transaction that
> fails and rolls back? Maybe look at all the lines that were inserted
> with that order, and try them manually in psql, character for character,
> and see if an error pops up for any of the lines?
>
> Terry Fielder
> terry@greatgulfhomes.com
> Associate Director Software Development and Deployment
> Great Gulf Homes / Ashton Woods Homes
> Fax: (416) 441-9085
>
>
>
> Rodrigo Gonzalez wrote:
>> Just to be sure....
>>
>> Any error msg in log?
>>
>> Maybe you can run this query in psql and see if it return any error msg
>>
>> Best regards
>>
>> Rodrigo
>>
>> HH wrote:
>>> Hello,
>>>
>>> I am running 8.1.3, built from source, on RHEL4/x64.
>>>
>>> I have a Web application that uses this database to sell products. We
>>> have
>>> an order table and an order lines table with a one to many relationship
>>> between them.
>>>
>>> For the past few months I have had a strange problem where sometimes
>>> (about
>>> 2% of orders), the line item rows disappear. By disappear I mean that
>>> they
>>> are committed to the database and then when I go to look at the order
>>> later,
>>> there are no line items. The row in the 'order' table still exists,
>>> it is
>>> just the line(s) that vanish.
>>>
>>> As I started looking into this problem I assumed that it was a bug in
>>> my Web
>>> application. I did some extensive testing and logging to no avail. I
>>> turned
>>> up the logging on my Web app and I can see the INSERTs but I never
>>> saw any
>>> DELETE statements though I can't find the child row(s) in the DB.
>>>
>>> I've been perplexed for quite some time so a few days ago I turned on
>>> the
>>> following PG logging:
>>>
>>> log_statement = 'mod'
>>>
>>> Today, I found an order that has this problem. Grepping my serverlog,
>>> I see
>>> the following:
>>>
>>> The line item is inserted:
>>>
>>> serverlog:LOG: statement: INSERT INTO order_lines ("order_description",
>>> "order_id", "updated_at", "band_name", "order_item", "product_id",
>>> "line_source", "order_quantity", "extended_price", "unit_price",
>>> "catalog_number", "created_at") VALUES('FW "Not My Pres" Trucker Hat',
>>> 16899, '2006-05-06 14:43:38', NULL, 'Baseball Cap ', 165, 'Merch', 1,
>>> NULL,
>>> 7.0, 94, '2006-05-06 14:43:38')
>>>
>>> Then, I do a SELECT:
>>>
>>> fw_production=# SELECT COUNT(*) FROM order_lines WHERE order_id = 16899;
>>> count -------
>>> 0
>>>
>>> There was about 3 hours between when the line was inserted and when I
>>> went
>>> to look for it. There is no DELETE in the serverlog for this row.
>>>
>>> I can't figure out where this row went and why it disappeared! Is it
>>> getting
>>> deleted some other way that wouldn't be logged? Am I missing something
>>> rudimentary?
>>>
>>> Any help is appreciated.
>>>
>>> Hunter
>>>
>>>
>>>
>>> ---------------------------(end of broadcast)---------------------------
>>> TIP 9: In versions below 8.0, the planner will ignore your desire to
>>> choose an index scan if your joining column's datatypes do not
>>> match
>>>
>>>
>>
>> ---------------------------(end of broadcast)---------------------------
>> TIP 5: don't forget to increase your free space map settings
>>



---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend

HH <lists@lastonepicked.com> writes:
> I can't figure out where this row went and why it disappeared! Is it getting
> deleted some other way that wouldn't be logged? Am I missing something
> rudimentary?

Aside from the suggestion already made that the inserting transaction
got rolled back instead of committed, I'd wonder about indirect
deletions due to ON DELETE CASCADE foreign keys, or deletions executed
by PL-language functions. Neither of those would produce obvious log
entries for their effects...

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql.org so that your
message can get through to the mailing list cleanly

Thanks Tom.

I don't use any PL language functions in my app explicitly but perhaps
something implicit when using one of the command line tools or something
like that? I don't have anything pointing in that direction.

I double checked the definition for the 'orders' table (header) and also the
'order_lines', just to make sure there wasn't something in there that could
be throwing me off.

I didn't see anything in 'orders' of any interest at all. I've included both
below in case I missed something in there.

I appreciate everyone trying to help and any other ideas are very much
appreciated. I hope to be able to trace the cause at some point.

-
db_production=# \d orders
Table "public.orders"
Column | Type |
Modifiers
------------------------+-----------------------------+---------------------
--------------------------------
id | integer | not null default
nextval('orders_id_seq'::regclass)
billing_address_1 | character varying(255) |
billing_address_2 | character varying(255) |
billing_city | character varying(255) |
billing_state_province | character varying(255) |
billing_postal_code | character varying(255) |
billing_country | character varying(255) |
phone_number | character varying(255) |
email_address | character varying(255) |
store_name | character varying(255) |
cardholders_name | character varying(255) |
card_type | character varying(255) |
card_number | character varying(255) |
card_security_code | character varying(255) |
expires_month | character varying(255) |
expires_year | character varying(255) |
sent_to_gateway | timestamp without time zone |
gateway_confirmation | character varying(255) |
avs_address | character varying(255) |
avs_zip_code | character varying(255) |
created_at | timestamp without time zone |
updated_at | timestamp without time zone |
billing_first_name | character varying(255) |
billing_last_name | character varying(255) |
shipping_cost | double precision |
sales_tax | double precision |
order_status | character varying(255) |
processor_type | character varying(255) |
ipn_notification | character varying(255) |
ipn_date | timestamp without time zone |
ipn_email | character varying(255) |
ip_address | character varying(255) |
Indexes:
"orders_pkey" PRIMARY KEY, btree (id)
"orders_order_status_index" btree (order_status)

'order_lines'

fatwreck_production=# \d order_lines;
Table "public.order_lines"
Column | Type |
Modifiers
-------------------+-----------------------------+--------------------------
--------------------------------
id | integer | not null default
nextval('order_lines_id_seq'::regclass)
order_id | integer |
order_item | character varying(255) |
order_description | character varying(255) |
order_quantity | integer |
unit_price | numeric |
extended_price | numeric |
created_at | timestamp without time zone |
updated_at | timestamp without time zone |
band_name | character varying(255) |
catalog_number | character varying(255) |
product_id | character varying(255) |
line_source | character varying(255) |
Indexes:
"order_lines_pkey" PRIMARY KEY, btree (id)
"order_lines_order_id_index" btree (order_id)
Foreign-key constraints:
"order_lines_order_id_fkey" FOREIGN KEY (order_id) REFERENCES orders(id)


> From: Tom Lane <tgl@sss.pgh.pa.us>
> Date: Sat, 06 May 2006 22:04:56 -0400
> To: HH <lists@lastonepicked.com>
> Cc: PostgreSQL <pgsql-general@postgresql.org>
> Subject: Re: [GENERAL] Can't Figure Out Where Rows Are Going
>
> HH <lists@lastonepicked.com> writes:
>> I can't figure out where this row went and why it disappeared! Is it getting
>> deleted some other way that wouldn't be logged? Am I missing something
>> rudimentary?
>
> Aside from the suggestion already made that the inserting transaction
> got rolled back instead of committed, I'd wonder about indirect
> deletions due to ON DELETE CASCADE foreign keys, or deletions executed
> by PL-language functions. Neither of those would produce obvious log
> entries for their effects...
>
> regards, tom lane



---------------------------(end of broadcast)---------------------------
TIP 3: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faq

If you're using a (java) web app with a connection pool is there a
possibility that some connections are configured with auto-commit=false
and that some future transaction issues a rollback which may include the
insert of the order items?

Perhaps some kind of persistance manager is doing this without your
realising it (hibernate, JDO etc)

Or that the connection pool recycled the connection without issuing a
commit.

Although that doesn't necessarily explain why you can see the rows
outside of that particular transaction...

If this is a java app, try asking the postgres-jdbc list.

John

HH wrote:
> Thanks Tom.
>
> I don't use any PL language functions in my app explicitly but perhaps
> something implicit when using one of the command line tools or something
> like that? I don't have anything pointing in that direction.
>
> I double checked the definition for the 'orders' table (header) and also the
> 'order_lines', just to make sure there wasn't something in there that could
> be throwing me off.
>
> I didn't see anything in 'orders' of any interest at all. I've included both
> below in case I missed something in there.
>
> I appreciate everyone trying to help and any other ideas are very much
> appreciated. I hope to be able to trace the cause at some point.
>
> -
> db_production=# \d orders
> Table "public.orders"
> Column | Type |
> Modifiers
> ------------------------+-----------------------------+---------------------
> --------------------------------
> id | integer | not null default
> nextval('orders_id_seq'::regclass)
> billing_address_1 | character varying(255) |
> billing_address_2 | character varying(255) |
> billing_city | character varying(255) |
> billing_state_province | character varying(255) |
> billing_postal_code | character varying(255) |
> billing_country | character varying(255) |
> phone_number | character varying(255) |
> email_address | character varying(255) |
> store_name | character varying(255) |
> cardholders_name | character varying(255) |
> card_type | character varying(255) |
> card_number | character varying(255) |
> card_security_code | character varying(255) |
> expires_month | character varying(255) |
> expires_year | character varying(255) |
> sent_to_gateway | timestamp without time zone |
> gateway_confirmation | character varying(255) |
> avs_address | character varying(255) |
> avs_zip_code | character varying(255) |
> created_at | timestamp without time zone |
> updated_at | timestamp without time zone |
> billing_first_name | character varying(255) |
> billing_last_name | character varying(255) |
> shipping_cost | double precision |
> sales_tax | double precision |
> order_status | character varying(255) |
> processor_type | character varying(255) |
> ipn_notification | character varying(255) |
> ipn_date | timestamp without time zone |
> ipn_email | character varying(255) |
> ip_address | character varying(255) |
> Indexes:
> "orders_pkey" PRIMARY KEY, btree (id)
> "orders_order_status_index" btree (order_status)
>
> 'order_lines'
>
> fatwreck_production=# \d order_lines;
> Table "public.order_lines"
> Column | Type |
> Modifiers
> -------------------+-----------------------------+--------------------------
> --------------------------------
> id | integer | not null default
> nextval('order_lines_id_seq'::regclass)
> order_id | integer |
> order_item | character varying(255) |
> order_description | character varying(255) |
> order_quantity | integer |
> unit_price | numeric |
> extended_price | numeric |
> created_at | timestamp without time zone |
> updated_at | timestamp without time zone |
> band_name | character varying(255) |
> catalog_number | character varying(255) |
> product_id | character varying(255) |
> line_source | character varying(255) |
> Indexes:
> "order_lines_pkey" PRIMARY KEY, btree (id)
> "order_lines_order_id_index" btree (order_id)
> Foreign-key constraints:
> "order_lines_order_id_fkey" FOREIGN KEY (order_id) REFERENCES orders(id)
>
>
>
>>From: Tom Lane <tgl@sss.pgh.pa.us>
>>Date: Sat, 06 May 2006 22:04:56 -0400
>>To: HH <lists@lastonepicked.com>
>>Cc: PostgreSQL <pgsql-general@postgresql.org>
>>Subject: Re: [GENERAL] Can't Figure Out Where Rows Are Going
>>
>>HH <lists@lastonepicked.com> writes:
>>
>>>I can't figure out where this row went and why it disappeared! Is it getting
>>>deleted some other way that wouldn't be logged? Am I missing something
>>>rudimentary?
>>
>>Aside from the suggestion already made that the inserting transaction
>>got rolled back instead of committed, I'd wonder about indirect
>>deletions due to ON DELETE CASCADE foreign keys, or deletions executed
>>by PL-language functions. Neither of those would produce obvious log
>>entries for their effects...
>>
>>regards, tom lane
>
>
>
>
> ---------------------------(end of broadcast)---------------------------
> TIP 3: Have you checked our extensive FAQ?
>
> http://www.postgresql.org/docs/faq

---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend

Tom Lane wrote:
> Aside from the suggestion already made that the inserting transaction
> got rolled back instead of committed, I'd wonder about indirect
> deletions due to ON DELETE CASCADE foreign keys, or deletions executed
> by PL-language functions. Neither of those would produce obvious log
> entries for their effects...
>
Is there no way to trace all SQL statements executed including
PL-language functions? There is at least one functional unit in
PostgreSQL (the optimizer for example) which does at least some
processing of all SQL statements, I presume.

Thanks
Peter

---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql.org so that your
message can get through to the mailing list cleanly

Are the relevant COMMITs appearing in the log?

If the commits fail for whatever reason does/can the application (and
postgresql) log that?

If the commits are successful then you shouldn't have to need to look for
roll-backs.

It might be a good idea for teh webapp to log unsuccessful commits. And
maybe even log important commits that are successful.

Regards,

Link.

At 05:30 PM 5/6/2006 -0700, HH wrote:

>Thanks for taking the time to reply.
>
>If that was occurring, would the log show it? I don't see any sign of a
>roll-back occurring in the log and when I run the queries in psql, they seem
>to complete properly.



---------------------------(end of broadcast)---------------------------
TIP 3: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faq