Atomikos Forum
Prepared Transaction Does Not Exist |
Hi All,
We may have made some progress on persistent "Prepared transaction ... does not exist" messages showing up in PostgreSQL logs using Atomikos and Hibernate/JPA. Adding com.atomikos.icatch.serial_jta_transactions=false to jta.properties really seems to have cut down on the number of these generated by our systems.
That said, it does not eliminate these messages completely. We have noticed any error between Atomikos and PostgreSQL results in these messages repeatedly showing up in PostgreSQL logs until the process in which the error occurred is killed. It seems there is an Atomikos thread that keeps the tx id around and tries to clean the tx up every 10 seconds forever. Unfortunately PostgreSQL is pretty good at nuking prepared transactions in error cases, which makes sense. Why would we want to keep transactions around when they've failed? So, Atomikos keeps asking PostgreSQL about the tx, and PostgreSQL keeps saying it doesn't know what Atomikos is talking about. Setting com.atomikos.icatch.threaded_2pc=false does not solve this.
My question is why does Atomikos attempt to clean up a tx forever? I understand the need for retry, especially since Atomikos code cannot know what the network looks like between the database client and server. However, retrying at the same frequency forever seems to be a little overly simplistic for this situation. We've seen the number of these messages in PostgreSQL logs increase to over 15/second. We are a little concerned this could lead to so much resource usage retrying it impacts application behavior. Indeed, we have several inexplicable intermittent errors that pop up whenever the retry rates get too high. It seems we get into ant death spiral anti-pattern territory, caused by Atomikos' retrying.
Would an exponential backoff strategy, perhaps with a maximum number of retries be a better fit for retry threads in Atomikos?
Thank you,
-- Tim
We may have made some progress on persistent "Prepared transaction ... does not exist" messages showing up in PostgreSQL logs using Atomikos and Hibernate/JPA. Adding com.atomikos.icatch.serial_jta_transactions=false to jta.properties really seems to have cut down on the number of these generated by our systems.
That said, it does not eliminate these messages completely. We have noticed any error between Atomikos and PostgreSQL results in these messages repeatedly showing up in PostgreSQL logs until the process in which the error occurred is killed. It seems there is an Atomikos thread that keeps the tx id around and tries to clean the tx up every 10 seconds forever. Unfortunately PostgreSQL is pretty good at nuking prepared transactions in error cases, which makes sense. Why would we want to keep transactions around when they've failed? So, Atomikos keeps asking PostgreSQL about the tx, and PostgreSQL keeps saying it doesn't know what Atomikos is talking about. Setting com.atomikos.icatch.threaded_2pc=false does not solve this.
My question is why does Atomikos attempt to clean up a tx forever? I understand the need for retry, especially since Atomikos code cannot know what the network looks like between the database client and server. However, retrying at the same frequency forever seems to be a little overly simplistic for this situation. We've seen the number of these messages in PostgreSQL logs increase to over 15/second. We are a little concerned this could lead to so much resource usage retrying it impacts application behavior. Indeed, we have several inexplicable intermittent errors that pop up whenever the retry rates get too high. It seems we get into ant death spiral anti-pattern territory, caused by Atomikos' retrying.
Would an exponential backoff strategy, perhaps with a maximum number of retries be a better fit for retry threads in Atomikos?
Thank you,
-- Tim
Every enterprise transaction Manager must support D(Acid) part of the ACID, this is typicall done via logging mechanism. It is better to pay for performance at the cost of data loss or data corruption. That is what is being provided by the transaction recovery modules in TM.
I think you can control the recovery scanning by configuring here
com.atomikos.icatch.checkpoint_interval
It seems that if you set the higher for above configuration it would logically stop the recovery cycle and hence you won't see much logging at DB level which seems to be appearing due to failure in recovery cycle. But make sure that you understand that Duribilty is very important aspect of transaction.
I would recommend you to take investigate the cause of receovery failures if you really want to avoid data corruption.
I am curious to know if you did take a look at this section
http://www.atomikos.com/Documentation/JtaProperties#Transaction_logs
PS: I am in process of taking a look at code.
Regards,
-VK
I think you can control the recovery scanning by configuring here
com.atomikos.icatch.checkpoint_interval
It seems that if you set the higher for above configuration it would logically stop the recovery cycle and hence you won't see much logging at DB level which seems to be appearing due to failure in recovery cycle. But make sure that you understand that Duribilty is very important aspect of transaction.
I would recommend you to take investigate the cause of receovery failures if you really want to avoid data corruption.
I am curious to know if you did take a look at this section
http://www.atomikos.com/Documentation/JtaProperties#Transaction_logs
PS: I am in process of taking a look at code.
Regards,
-VK
Vicky Kak 
Thursday, November 18, 2010
Thursday, November 18, 2010
Also can you please attach the DB logs from the postgresDB, I would like to take a look at it.
Regards,
-VK
Regards,
-VK
Vicky Kak
Thursday, November 18, 2010
Thursday, November 18, 2010
Here's a sample from a test environment. I kicked off a batch job to do some calculations on our data. It ran overnight. When I got back to it the next morning, the Atomikos retry thread was preventing the process from ending, and there were a ton of these in the logs. This one is nice because there was only one failed tx, so you can see it repeat easily. The initial fail was caused by a lock on one of the tables. The statement blocked until the Atomikos timeout kicked in. I'm not including the full logs, but the same pattern pretty much repeats for 7 hours until I killed the hanging process the next morning.
Nov 16 22:44:27 astro postgres[30454]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
Nov 16 22:44:27 astro postgres[30454]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 16 22:44:37 astro postgres[12152]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
Nov 16 22:44:37 astro postgres[12152]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 16 22:44:47 astro postgres[12155]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
Nov 16 22:44:47 astro postgres[12155]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 16 22:44:59 astro postgres[12159]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
Nov 16 22:44:59 astro postgres[12159]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 16 22:45:09 astro postgres[12162]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
<snip>
Nov 16 23:45:09 astro postgres[17350]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 16 23:45:39 astro postgres[17417]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
Nov 16 23:45:39 astro postgres[17417]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 16 23:45:49 astro postgres[17422]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
Nov 16 23:45:49 astro postgres[17422]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 16 23:45:59 astro postgres[17424]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
<snip>
Nov 17 03:19:26 astro postgres[2572]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
Nov 17 03:19:26 astro postgres[2572]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 17 03:19:36 astro postgres[2575]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
Nov 17 03:19:36 astro postgres[2575]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 17 03:19:46 astro postgres[2578]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
<snip>
Nov 17 05:06:06 astro postgres[11893]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
Nov 17 05:06:06 astro postgres[11893]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 17 05:06:16 astro postgres[11896]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
Nov 17 05:06:16 astro postgres[11896]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 17 05:06:16 astro postgres[11898]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
<snip>
Nov 17 05:47:05 astro postgres[15288]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
Nov 17 05:47:05 astro postgres[15288]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 17 05:47:15 astro postgres[15291]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
Nov 17 05:47:15 astro postgres[15291]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 17 05:47:26 astro postgres[15354]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
Nov 17 05:47:26 astro postgres[15354]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 16 22:44:27 astro postgres[30454]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
Nov 16 22:44:27 astro postgres[30454]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 16 22:44:37 astro postgres[12152]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
Nov 16 22:44:37 astro postgres[12152]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 16 22:44:47 astro postgres[12155]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
Nov 16 22:44:47 astro postgres[12155]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 16 22:44:59 astro postgres[12159]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
Nov 16 22:44:59 astro postgres[12159]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 16 22:45:09 astro postgres[12162]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
<snip>
Nov 16 23:45:09 astro postgres[17350]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 16 23:45:39 astro postgres[17417]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
Nov 16 23:45:39 astro postgres[17417]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 16 23:45:49 astro postgres[17422]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
Nov 16 23:45:49 astro postgres[17422]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 16 23:45:59 astro postgres[17424]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
<snip>
Nov 17 03:19:26 astro postgres[2572]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
Nov 17 03:19:26 astro postgres[2572]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 17 03:19:36 astro postgres[2575]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
Nov 17 03:19:36 astro postgres[2575]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 17 03:19:46 astro postgres[2578]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
<snip>
Nov 17 05:06:06 astro postgres[11893]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
Nov 17 05:06:06 astro postgres[11893]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 17 05:06:16 astro postgres[11896]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
Nov 17 05:06:16 astro postgres[11896]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 17 05:06:16 astro postgres[11898]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
<snip>
Nov 17 05:47:05 astro postgres[15288]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
Nov 17 05:47:05 astro postgres[15288]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 17 05:47:15 astro postgres[15291]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
Nov 17 05:47:15 astro postgres[15291]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Nov 17 05:47:26 astro postgres[15354]: [2-1] ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk=" does not exist
Nov 17 05:47:26 astro postgres[15354]: [2-2] STATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTkwMDA0NA==_MTkyLjE2OC4xNjguMjUwLnRtMjU4MTk='
Tim,
Not sure if I understand correctly, but if prepared transactions are nuked then PostgreSQL should remember their Xids and return them upon recovery.
Subsequent commit retries (like Atomikos does) will stop once PostgreSQL then throws the (spec-required) HeuristicRollbackException.
If there is no such exception, the TM will pessimistically retry.
HTH
Not sure if I understand correctly, but if prepared transactions are nuked then PostgreSQL should remember their Xids and return them upon recovery.
Subsequent commit retries (like Atomikos does) will stop once PostgreSQL then throws the (spec-required) HeuristicRollbackException.
If there is no such exception, the TM will pessimistically retry.
HTH
Guy Pardon 
Saturday, November 20, 2010
Saturday, November 20, 2010
PostgreSQL remembers transactions that have been prepared. If Atomikos is asking for a transaction id that PostgreSQL thinks doesn't exist then its fairly simple: one of them is wrong. The question is: who?
Please can we verify that Atomikos has received a prepare for that transaction id? Logs etc??
POstgreSQL logging can be enabled with log_statement = all though that is incredibly verbose.
Please can we verify that Atomikos has received a prepare for that transaction id? Logs etc??
POstgreSQL logging can be enabled with log_statement = all though that is incredibly verbose.
Logs at INFO level should show what is prepared in Atomikos - except our current M4 build has a bug in the log levels. Our upcoming M5 build should work - ETA Monday evening.
That being said, we don't retry commits unless things were prepared.
Suggestion: did you try with com.atomikos.icatch.threaded_2pc=false? See http://www.atomikos.com/Documentation/JtaProperties
HTH
That being said, we don't retry commits unless things were prepared.
Suggestion: did you try with com.atomikos.icatch.threaded_2pc=false? See http://www.atomikos.com/Documentation/JtaProperties
HTH
Guy Pardon
Saturday, November 20, 2010
Saturday, November 20, 2010
Hi All,
Thanks a lot for getting back with me. I've got a set of logs which should capture what's going on. Here's the jta.properties we're using:
com.atomikos.icatch.service=com.atomikos.icatch.standalone.UserTransactionServiceFactory
com.atomikos.icatch.output_dir=/opt/smoothie/tmp
com.atomikos.icatch.log_base_dir=/opt/smoothie/tmp
com.atomikos.icatch.console_log_level=DEBUG
com.atomikos.icatch.max_timeout=600000
com.atomikos.icatch.threaded_2pc=false
com.atomikos.icatch.serial_jta_transactions=false
And here's a snippet from the full postgres logs showing the initial prepare, what ran inside the transaction, a rollback at the end and the first of the repeating series of "prepared transaction does not exist" message:
Nov 23 08:09:08 astro postgres[1156]: [1184453-1] 2010-11-23 08:09:08 PSTLOG: 00000: execute <unnamed>: PREPARE TRANSACTION '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjE2OTgwMDAwMg==_MTkyLjE2OC4xNjguMjUwLnRtNTM2OTk='
Nov 23 08:09:08 astro postgres[1156]: [1184453-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:1972
Nov 23 08:09:08 astro postgres[1574]: [4483-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 72.442 ms
Nov 23 08:09:08 astro postgres[1574]: [4483-2] 2010-11-23 08:09:08 PSTLOCATION: exec_bind_message, postgres.c:1826
Nov 23 08:09:08 astro postgres[1574]: [4484-1] 2010-11-23 08:09:08 PSTLOG: 00000: execute <unnamed>: select advertisem0_.BASEUUID as uuid36_, advertisem0_1_.creationDate as creation2_36_, advertisem0_1_.depth as depth36_, advertisem0_1_.leftLimit as leftLimit36_, advertisem0_1_.modifiedDate as modified5_36_, advertisem0_1_.parent_uuid as parent6_36_, advertisem0_1_.rightLimit as rightLimit36_, advertisem0_1_.rootuuid as rootuuid36_, advertisem0_1_.text as text36_, advertisem0_1_.version as version36_, advertisem0_.aceScore as aceScore37_, advertisem0_.advertisementAgency_id as adverti27_37_, advertisem0_.PARENT_UUID as PARENT28_37_, advertisem0_.advertisementCompany_id as adverti29_37_, advertisem0_.advertisementMedia_id as adverti30_37_, advertisem0_.advertisementProduct_id as adverti31_37_, advertisem0_.advertisementStatus as advertis2_37_, advertisem0_.airDate as airDate37_, advertisem0_.attention as attention37_, advertisem0_.classic as classic37_, advertisem0_.country as country37_, advertisem0_.descri
Nov 23 08:09:08 astro postgres[1574]: [4484-2] desire37_, advertisem0_.hasBrandAssociation as hasBrand9_37_, advertisem0_.information as informa10_37_, advertisem0_.innovation as innovation37_, advertisem0_.language as language37_, advertisem0_.length as length37_, advertisem0_.liking as liking37_, advertisem0_.location as location37_, advertisem0_.numberOfRespondents as numberO16_37_, advertisem0_.partner_id as partner32_37_, advertisem0_.partnerId as partnerId37_, advertisem0_.persuasion as persuasion37_, advertisem0_.preCalcStatus as preCalc19_37_, advertisem0_.publicAd as publicAd37_, advertisem0_.readyToReportDate as readyTo21_37_, advertisem0_.relevance as relevance37_, advertisem0_.tagline as tagline37_, advertisem0_.title as title37_, advertisem0_.watchability as watchab25_37_ from ADVERTISEMENT_HIERARCHY advertisem0_ inner join AdvertisementHierarchyMetadata advertisem0_1_ on advertisem0_.BASEUUID=advertisem0_1_.uuid where advertisem0_.BASEUUID=$1 limit $2
Nov 23 08:09:08 astro postgres[1574]: [4484-3] 2010-11-23 08:09:08 PSTDETAIL: parameters: $1 = 'e9482a0c-611d-4439-866f-8c11972ec6cc', $2 = '2'
Nov 23 08:09:08 astro postgres[1574]: [4484-4] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:1972
Nov 23 08:09:08 astro postgres[1574]: [4485-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.138 ms
Nov 23 08:09:08 astro postgres[1574]: [4485-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:2043
Nov 23 08:09:08 astro postgres[1574]: [4486-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.039 ms
Nov 23 08:09:08 astro postgres[1574]: [4486-2] 2010-11-23 08:09:08 PSTLOCATION: exec_parse_message, postgres.c:1409
Nov 23 08:09:08 astro postgres[1574]: [4487-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.022 ms
Nov 23 08:09:08 astro postgres[1574]: [4487-2] 2010-11-23 08:09:08 PSTLOCATION: exec_bind_message, postgres.c:1826
Nov 23 08:09:08 astro postgres[1574]: [4488-1] 2010-11-23 08:09:08 PSTLOG: 00000: execute <unnamed>: SELECT current_timestamp
Nov 23 08:09:08 astro postgres[1574]: [4488-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:1972
Nov 23 08:09:08 astro postgres[1574]: [4489-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.062 ms
Nov 23 08:09:08 astro postgres[1574]: [4489-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:2043
Nov 23 08:09:08 astro postgres[1574]: [4490-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.248 ms
Nov 23 08:09:08 astro postgres[1574]: [4490-2] 2010-11-23 08:09:08 PSTLOCATION: exec_parse_message, postgres.c:1409
Nov 23 08:09:08 astro postgres[1574]: [4491-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.277 ms
Nov 23 08:09:08 astro postgres[1574]: [4491-2] 2010-11-23 08:09:08 PSTLOCATION: exec_bind_message, postgres.c:1826
Nov 23 08:09:08 astro postgres[1574]: [4492-1] 2010-11-23 08:09:08 PSTLOG: 00000: execute <unnamed>: update Advertisement set creationDate=$1, modifiedDate=$2, uuid=$3, version=$4, aceScore=$5, advertisementAgency_id=$6, advertisementBrand_id=$7, advertisementCompany_id=$8, advertisementMedia_id=$9, advertisementProduct_id=$10, advertisementStatus=$11, airDate=$12, attention=$13, classic=$14, country=$15, covey_id=$16, description=$17, desire=$18, hasBrandAssociation=$19, information=$20, innovation=$21, intender_id=$22, language=$23, length=$24, liking=$25, location=$26, numberOfRespondents=$27, partner_id=$28, partnerId=$29, persuasion=$30, preCalcStatus=$31, publicAd=$32, readyToReportDate=$33, relevance=$34, tagline=$35, title=$36, watchability=$37 where id=$38 and version=$39
Nov 23 08:09:08 astro postgres[1574]: [4492-2] 2010-11-23 08:09:08 PSTDETAIL: parameters: $1 = '2010-11-08 13:01:15.862', $2 = '2010-11-23 08:09:08.445', $3 = 'e9482a0c-611d-4439-866f-8c11972ec6cc', $4 = '10', $5 = '478.20976244039423', $6 = '150522026', $7 = '103494509', $8 = '134239040', $9 = '1', $10 = '6', $11 = '2', $12 = '2010-11-04 00:00:00', $13 = '625.712171811948', $14 = 'f', $15 = 'US', $16 = NULL, $17 = 'A group of men are at a bar. Man I got this round. He turns to walk toward the bar and performs various football actions as the M-Annc calls them. He finally is able to get to the bar and order. M-Annc states to call your own audible for a chance to win a trip to the hottest party in Dallas. Text: [BUD LIGHT HOTEL DALLAS] Go to ESPN.com search Bud Light.', $18 = '485.55699172583746', $19 = 't', $20 = '482.57421707217497', $21 = '551.76823352267138', $22 = '145734000', $23 = 'en', $24 = '30', $25 = '609.77250584759156', $26 = '2535489.flv', $27 = '622', $28 = '3', $29 = '2535489', $30 = '530.1470
Nov 23 08:09:08 astro postgres[1574]: [4492-3] '2010-11-08 18:59:33.362', $34 = '493.60195519423928', $35 = '', $36 = 'Bud Light Hotel Dallas', $37 = '556.90699953369278', $38 = '9914', $39 = '9'
Nov 23 08:09:08 astro postgres[1574]: [4492-4] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:1972
Nov 23 08:09:08 astro postgres[1574]: [4493-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.840 ms
Nov 23 08:09:08 astro postgres[1574]: [4493-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:2043
Nov 23 08:09:08 astro postgres[1156]: [1184454-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 36.975 ms
Nov 23 08:09:08 astro postgres[1156]: [1184454-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:2043
Nov 23 08:09:08 astro postgres[1574]: [4494-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.038 ms
Nov 23 08:09:08 astro postgres[1574]: [4494-2] 2010-11-23 08:09:08 PSTLOCATION: exec_parse_message, postgres.c:1409
Nov 23 08:09:08 astro postgres[1574]: [4495-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.018 ms
Nov 23 08:09:08 astro postgres[1574]: [4495-2] 2010-11-23 08:09:08 PSTLOCATION: exec_bind_message, postgres.c:1826
Nov 23 08:09:08 astro postgres[1574]: [4496-1] 2010-11-23 08:09:08 PSTLOG: 00000: execute <unnamed>: SELECT current_timestamp
Nov 23 08:09:08 astro postgres[1574]: [4496-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:1972
Nov 23 08:09:08 astro postgres[1574]: [4497-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.058 ms
Nov 23 08:09:08 astro postgres[1574]: [4497-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:2043
Nov 23 08:09:08 astro postgres[1574]: [4498-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.266 ms
Nov 23 08:09:08 astro postgres[1574]: [4498-2] 2010-11-23 08:09:08 PSTLOCATION: exec_parse_message, postgres.c:1409
Nov 23 08:09:08 astro postgres[1574]: [4499-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.181 ms
Nov 23 08:09:08 astro postgres[1574]: [4499-2] 2010-11-23 08:09:08 PSTLOCATION: exec_bind_message, postgres.c:1826
Nov 23 08:09:08 astro postgres[1574]: [4500-1] 2010-11-23 08:09:08 PSTLOG: 00000: execute <unnamed>: select advertisem0_.id as id23_, advertisem0_.creationDate as creation2_23_, advertisem0_.modifiedDate as modified3_23_, advertisem0_.uuid as uuid23_, advertisem0_.version as version23_, advertisem0_.aceScore as aceScore23_, advertisem0_.advertisementAgency_id as adverti31_23_, advertisem0_.advertisementBrand_id as adverti32_23_, advertisem0_.advertisementCompany_id as adverti33_23_, advertisem0_.advertisementMedia_id as adverti34_23_, advertisem0_.advertisementProduct_id as adverti35_23_, advertisem0_.advertisementStatus as advertis7_23_, advertisem0_.airDate as airDate23_, advertisem0_.attention as attention23_, advertisem0_.classic as classic23_, advertisem0_.country as country23_, advertisem0_.covey_id as covey36_23_, advertisem0_.description as descrip12_23_, advertisem0_.desire as desire23_, advertisem0_.hasBrandAssociation as hasBran14_23_, advertisem0_.information as informa15_23_, advertisem0_.innov
Nov 23 08:09:08 astro postgres[1574]: [4500-2] as intender37_23_, advertisem0_.language as language23_, advertisem0_.length as length23_, advertisem0_.liking as liking23_, advertisem0_.location as location23_, advertisem0_.numberOfRespondents as numberO21_23_, advertisem0_.partner_id as partner38_23_, advertisem0_.partnerId as partnerId23_, advertisem0_.persuasion as persuasion23_, advertisem0_.preCalcStatus as preCalc24_23_, advertisem0_.publicAd as publicAd23_, advertisem0_.readyToReportDate as readyTo26_23_, advertisem0_.relevance as relevance23_, advertisem0_.tagline as tagline23_, advertisem0_.title as title23_, advertisem0_.watchability as watchab30_23_ from Advertisement advertisem0_ where advertisem0_.uuid=$1 limit $2
Nov 23 08:09:08 astro postgres[1574]: [4500-3] 2010-11-23 08:09:08 PSTDETAIL: parameters: $1 = 'e9482a0c-611d-4439-866f-8c11972ec6cc', $2 = '2'
Nov 23 08:09:08 astro postgres[1574]: [4500-4] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:1972
Nov 23 08:09:08 astro postgres[1574]: [4501-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.216 ms
Nov 23 08:09:08 astro postgres[1574]: [4501-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:2043
Nov 23 08:09:08 astro postgres[1573]: [16-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.354 ms
Nov 23 08:09:08 astro postgres[1573]: [16-2] 2010-11-23 08:09:08 PSTLOCATION: exec_parse_message, postgres.c:1409
Nov 23 08:09:08 astro postgres[1573]: [17-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.026 ms
Nov 23 08:09:08 astro postgres[1573]: [17-2] 2010-11-23 08:09:08 PSTLOCATION: exec_bind_message, postgres.c:1826
Nov 23 08:09:08 astro postgres[1573]: [18-1] 2010-11-23 08:09:08 PSTLOG: 00000: execute <unnamed>: SELECT gid FROM pg_prepared_xacts
Nov 23 08:09:08 astro postgres[1573]: [18-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:1972
Nov 23 08:09:08 astro postgres[1573]: [19-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.078 ms
Nov 23 08:09:08 astro postgres[1573]: [19-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:2043
Nov 23 08:09:08 astro postgres[1573]: [20-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.043 ms
Nov 23 08:09:08 astro postgres[1573]: [20-2] 2010-11-23 08:09:08 PSTLOCATION: exec_parse_message, postgres.c:1409
Nov 23 08:09:08 astro postgres[1573]: [21-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.005 ms
Nov 23 08:09:08 astro postgres[1573]: [21-2] 2010-11-23 08:09:08 PSTLOCATION: exec_bind_message, postgres.c:1826
Nov 23 08:09:08 astro postgres[1573]: [22-1] 2010-11-23 08:09:08 PSTLOG: 00000: execute <unnamed>: ROLLBACK PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjE2OTgwMDAwMg==_MTkyLjE2OC4xNjguMjUwLnRtNTM2OTk='
Nov 23 08:09:08 astro postgres[1573]: [22-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:1972
Nov 23 08:09:08 astro postgres[1573]: [23-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 16.766 ms
Nov 23 08:09:08 astro postgres[1573]: [23-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:2043
Nov 23 08:09:08 astro postgres[1587]: [12-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.261 ms
Nov 23 08:09:08 astro postgres[1587]: [12-2] 2010-11-23 08:09:08 PSTLOCATION: exec_parse_message, postgres.c:1409
Nov 23 08:09:08 astro postgres[1587]: [13-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.025 ms
Nov 23 08:09:08 astro postgres[1587]: [13-2] 2010-11-23 08:09:08 PSTLOCATION: exec_bind_message, postgres.c:1826
Nov 23 08:09:08 astro postgres[1587]: [14-1] 2010-11-23 08:09:08 PSTLOG: 00000: execute <unnamed>: SELECT gid FROM pg_prepared_xacts
Nov 23 08:09:08 astro postgres[1587]: [14-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:1972
Nov 23 08:09:08 astro postgres[1587]: [15-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.060 ms
Nov 23 08:09:08 astro postgres[1587]: [15-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:2043
Nov 23 08:09:08 astro postgres[1602]: [8-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.331 ms
Nov 23 08:09:08 astro postgres[1602]: [8-2] 2010-11-23 08:09:08 PSTLOCATION: exec_parse_message, postgres.c:1409
Nov 23 08:09:08 astro postgres[1602]: [9-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.025 ms
Nov 23 08:09:08 astro postgres[1602]: [9-2] 2010-11-23 08:09:08 PSTLOCATION: exec_bind_message, postgres.c:1826
Nov 23 08:09:08 astro postgres[1602]: [10-1] 2010-11-23 08:09:08 PSTLOG: 00000: execute <unnamed>: SELECT gid FROM pg_prepared_xacts
Nov 23 08:09:08 astro postgres[1602]: [10-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:1972
Nov 23 08:09:08 astro postgres[1602]: [11-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.059 ms
Nov 23 08:09:08 astro postgres[1602]: [11-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:2043
Nov 23 08:09:08 astro postgres[12536]: [2-1] 2010-11-23 08:09:08 PSTLOG: 00000: connection received: host=192.168.168.250 port=52039
Nov 23 08:09:08 astro postgres[12536]: [2-2] 2010-11-23 08:09:08 PSTLOCATION: BackendInitialize, postmaster.c:3409
Nov 23 08:09:08 astro postgres[1156]: [1184455-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.037 ms
Nov 23 08:09:08 astro postgres[1156]: [1184455-2] 2010-11-23 08:09:08 PSTLOCATION: exec_parse_message, postgres.c:1409
Nov 23 08:09:08 astro postgres[1156]: [1184456-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.006 ms
Nov 23 08:09:08 astro postgres[1156]: [1184456-2] 2010-11-23 08:09:08 PSTLOCATION: exec_bind_message, postgres.c:1826
Nov 23 08:09:08 astro postgres[1156]: [1184457-1] 2010-11-23 08:09:08 PSTLOG: 00000: execute <unnamed>: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjE2OTgwMDAwMg==_MTkyLjE2OC4xNjguMjUwLnRtNTM2OTk='
Nov 23 08:09:08 astro postgres[1156]: [1184457-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:1972
Nov 23 08:09:08 astro postgres[1156]: [1184458-1] 2010-11-23 08:09:08 PSTERROR: 42704: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjE2OTgwMDAwMg==_MTkyLjE2OC4xNjguMjUwLnRtNTM2OTk=" does not exist
Nov 23 08:09:08 astro postgres[1156]: [1184458-2] 2010-11-23 08:09:08 PSTLOCATION: LockGXact, twophase.c:454
Nov 23 08:09:08 astro postgres[1156]: [1184458-3] 2010-11-23 08:09:08 PSTSTATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjE2OTgwMDAwMg==_MTkyLjE2OC4xNjguMjUwLnRtNTM2OTk='
And here's the output from tm.out:
10-11-23 05:46:44,891 [main] arcDataSource: refreshed XAResource
10-11-23 05:46:44,903 [main] surveyDataSource: refreshed XAResource
10-11-23 05:46:45,226 [main] smoothieDataSource: refreshed XAResource
10-11-23 05:46:45,392 [main] ssDataSource: refreshed XAResource
10-11-23 05:47:38,168 [main] Logfile closed: /opt/styx/tmp/styx_lucene/tmlog0.log
<snip>
10-11-23 08:08:43,507 [main] Logfile closed: /opt/styx/tmp/styx_lucene/tmlog213.log
10-11-23 08:09:08,630 [main] XA resource 'arcDataSource': commit for XID '3139322E3136382E3136382E3235302E746D32313639383030303032:3139322E3136382E3136382E3235302E746D3533363939' raised -3: the XA resource detected an internal error
org.postgresql.xa.PGXAException: Error committing prepared transaction
at org.postgresql.xa.PGXAConnection.commitPrepared(PGXAConnection.java:497)
at org.postgresql.xa.PGXAConnection.commit(PGXAConnection.java:420)
at com.atomikos.datasource.xa.XAResourceTransaction.commit(XAResourceTransaction.java:999)
at com.atomikos.icatch.imp.CommitMessage.send(CommitMessage.java:94)
at com.atomikos.icatch.imp.PropagationMessage.submit(PropagationMessage.java:86)
at com.atomikos.icatch.imp.Propagator$PropagatorThread.run(Propagator.java:62)
at com.atomikos.icatch.imp.Propagator.submitPropagationMessage(Propagator.java:41)
at com.atomikos.icatch.imp.CoordinatorStateHandler.commit(CoordinatorStateHandler.java:661)
at com.atomikos.icatch.imp.IndoubtStateHandler.commit(IndoubtStateHandler.java:225)
at com.atomikos.icatch.imp.CoordinatorImp.commit(CoordinatorImp.java:828)
at com.atomikos.icatch.imp.CoordinatorImp.terminate(CoordinatorImp.java:1127)
at com.atomikos.icatch.imp.CompositeTerminatorImp.commit(CompositeTerminatorImp.java:151)
at com.atomikos.icatch.jta.TransactionImp.commit(TransactionImp.java:317)
at com.atomikos.icatch.jta.TransactionManagerImp.commit(TransactionManagerImp.java:613)
at com.atomikos.icatch.jta.UserTransactionManager.commit(UserTransactionManager.java:149)
at org.hibernate.engine.transaction.Isolater$JtaDelegate.delegateWork(Isolater.java:137)
at org.hibernate.engine.transaction.Isolater.doIsolatedWork(Isolater.java:64)
at org.hibernate.engine.TransactionHelper.doWorkInNewTransaction(TransactionHelper.java:74)
at org.hibernate.id.enhanced.TableGenerator$1.getNextValue(TableGenerator.java:429)
at org.hibernate.id.enhanced.OptimizerFactory$PooledOptimizer.generate(OptimizerFactory.java:276)
at org.hibernate.id.enhanced.TableGenerator.generate(TableGenerator.java:426)
at org.hibernate.event.def.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:122)
at org.hibernate.ejb.event.EJB3PersistEventListener.saveWithGeneratedId(EJB3PersistEventListener.java:49)
at org.hibernate.event.def.DefaultPersistEventListener.entityIsTransient(DefaultPersistEventListener.java:154)
at org.hibernate.event.def.DefaultPersistEventListener.onPersist(DefaultPersistEventListener.java:110)
at org.hibernate.event.def.DefaultPersistEventListener.onPersist(DefaultPersistEventListener.java:61)
at org.hibernate.impl.SessionImpl.firePersist(SessionImpl.java:645)
at org.hibernate.impl.SessionImpl.persist(SessionImpl.java:619)
at org.hibernate.impl.SessionImpl.persist(SessionImpl.java:623)
at org.hibernate.ejb.AbstractEntityManagerImpl.persist(AbstractEntityManagerImpl.java:220)
at sun.reflect.GeneratedMethodAccessor180.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler.invoke(ExtendedEntityManagerCreator.java:365)
at $Proxy79.persist(Unknown Source)
at sun.reflect.GeneratedMethodAccessor180.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:240)
at $Proxy53.persist(Unknown Source)
at com.adratingco.daos.jpa.JpaAbstractDao.save(JpaAbstractDao.java:134)
at sun.reflect.GeneratedMethodAccessor184.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
at $Proxy65.save(Unknown Source)
at com.adratingco.riverstyx.roadies.NormCalculatorRoadie.computeNorm(NormCalculatorRoadie.java:145)
at com.adratingco.riverstyx.services.NormService.calculateAdvertisementNorm(NormService.java:53)
at sun.reflect.GeneratedMethodAccessor296.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
at $Proxy81.calculateAdvertisementNorm(Unknown Source)
at com.adratingco.riverstyx.json.apps.PreCalculator.preCalcAd(PreCalculator.java:38)
at com.adratingco.riverstyx.json.apps.PreCalculator$$FastClassByCGLIB$$156b1558.invoke(<generated>)
at net.sf.cglib.proxy.MethodProxy.invoke(MethodProxy.java:191)
at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:617)
at com.adratingco.riverstyx.json.apps.PreCalculator$$EnhancerByCGLIB$$ba6b594f.preCalcAd(<generated>)
at com.adratingco.riverstyx.json.apps.PreCalculator.main(PreCalculator.java:386)
Caused by: org.postgresql.util.PSQLException: ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjE2OTgwMDAwMg==_MTkyLjE2OC4xNjguMjUwLnRtNTM2OTk=" does not exist
at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2102)
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1835)
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:374)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:302)
at org.postgresql.xa.PGXAConnection.commitPrepared(PGXAConnection.java:487)
... 68 more
10-11-23 08:09:08,631 [main] Unexpected error in commit
com.atomikos.icatch.SysException: XA resource 'arcDataSource': commit for XID '3139322E3136382E3136382E3235302E746D32313639383030303032:3139322E3136382E3136382E3235302E746D3533363939' raised -3: the XA resource detected an internal error
at com.atomikos.datasource.xa.XAResourceTransaction.commit(XAResourceTransaction.java:1039)
at com.atomikos.icatch.imp.CommitMessage.send(CommitMessage.java:94)
at com.atomikos.icatch.imp.PropagationMessage.submit(PropagationMessage.java:86)
at com.atomikos.icatch.imp.Propagator$PropagatorThread.run(Propagator.java:62)
at com.atomikos.icatch.imp.Propagator.submitPropagationMessage(Propagator.java:41)
at com.atomikos.icatch.imp.CoordinatorStateHandler.commit(CoordinatorStateHandler.java:661)
at com.atomikos.icatch.imp.IndoubtStateHandler.commit(IndoubtStateHandler.java:225)
at com.atomikos.icatch.imp.CoordinatorImp.commit(CoordinatorImp.java:828)
at com.atomikos.icatch.imp.CoordinatorImp.terminate(CoordinatorImp.java:1127)
at com.atomikos.icatch.imp.CompositeTerminatorImp.commit(CompositeTerminatorImp.java:151)
at com.atomikos.icatch.jta.TransactionImp.commit(TransactionImp.java:317)
at com.atomikos.icatch.jta.TransactionManagerImp.commit(TransactionManagerImp.java:613)
at com.atomikos.icatch.jta.UserTransactionManager.commit(UserTransactionManager.java:149)
at org.hibernate.engine.transaction.Isolater$JtaDelegate.delegateWork(Isolater.java:137)
at org.hibernate.engine.transaction.Isolater.doIsolatedWork(Isolater.java:64)
at org.hibernate.engine.TransactionHelper.doWorkInNewTransaction(TransactionHelper.java:74)
at org.hibernate.id.enhanced.TableGenerator$1.getNextValue(TableGenerator.java:429)
at org.hibernate.id.enhanced.OptimizerFactory$PooledOptimizer.generate(OptimizerFactory.java:276)
at org.hibernate.id.enhanced.TableGenerator.generate(TableGenerator.java:426)
at org.hibernate.event.def.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:122)
at org.hibernate.ejb.event.EJB3PersistEventListener.saveWithGeneratedId(EJB3PersistEventListener.java:49)
at org.hibernate.event.def.DefaultPersistEventListener.entityIsTransient(DefaultPersistEventListener.java:154)
at org.hibernate.event.def.DefaultPersistEventListener.onPersist(DefaultPersistEventListener.java:110)
at org.hibernate.event.def.DefaultPersistEventListener.onPersist(DefaultPersistEventListener.java:61)
at org.hibernate.impl.SessionImpl.firePersist(SessionImpl.java:645)
at org.hibernate.impl.SessionImpl.persist(SessionImpl.java:619)
at org.hibernate.impl.SessionImpl.persist(SessionImpl.java:623)
at org.hibernate.ejb.AbstractEntityManagerImpl.persist(AbstractEntityManagerImpl.java:220)
at sun.reflect.GeneratedMethodAccessor180.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler.invoke(ExtendedEntityManagerCreator.java:365)
at $Proxy79.persist(Unknown Source)
at sun.reflect.GeneratedMethodAccessor180.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:240)
at $Proxy53.persist(Unknown Source)
at com.adratingco.daos.jpa.JpaAbstractDao.save(JpaAbstractDao.java:134)
at sun.reflect.GeneratedMethodAccessor184.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
at $Proxy65.save(Unknown Source)
at com.adratingco.riverstyx.roadies.NormCalculatorRoadie.computeNorm(NormCalculatorRoadie.java:145)
at com.adratingco.riverstyx.services.NormService.calculateAdvertisementNorm(NormService.java:53)
at sun.reflect.GeneratedMethodAccessor296.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
at $Proxy81.calculateAdvertisementNorm(Unknown Source)
at com.adratingco.riverstyx.json.apps.PreCalculator.preCalcAd(PreCalculator.java:38)
at com.adratingco.riverstyx.json.apps.PreCalculator$$FastClassByCGLIB$$156b1558.invoke(<generated>)
at net.sf.cglib.proxy.MethodProxy.invoke(MethodProxy.java:191)
at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:617)
at com.adratingco.riverstyx.json.apps.PreCalculator$$EnhancerByCGLIB$$ba6b594f.preCalcAd(<generated>)
at com.adratingco.riverstyx.json.apps.PreCalculator.main(PreCalculator.java:386)
The errors in postgres and atomikos logs repeat indefinitely after that. If you guys want full logs, any additional information, config changes or anything else, please let me know.
-- Tim
Thanks a lot for getting back with me. I've got a set of logs which should capture what's going on. Here's the jta.properties we're using:
com.atomikos.icatch.service=com.atomikos.icatch.standalone.UserTransactionServiceFactory
com.atomikos.icatch.output_dir=/opt/smoothie/tmp
com.atomikos.icatch.log_base_dir=/opt/smoothie/tmp
com.atomikos.icatch.console_log_level=DEBUG
com.atomikos.icatch.max_timeout=600000
com.atomikos.icatch.threaded_2pc=false
com.atomikos.icatch.serial_jta_transactions=false
And here's a snippet from the full postgres logs showing the initial prepare, what ran inside the transaction, a rollback at the end and the first of the repeating series of "prepared transaction does not exist" message:
Nov 23 08:09:08 astro postgres[1156]: [1184453-1] 2010-11-23 08:09:08 PSTLOG: 00000: execute <unnamed>: PREPARE TRANSACTION '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjE2OTgwMDAwMg==_MTkyLjE2OC4xNjguMjUwLnRtNTM2OTk='
Nov 23 08:09:08 astro postgres[1156]: [1184453-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:1972
Nov 23 08:09:08 astro postgres[1574]: [4483-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 72.442 ms
Nov 23 08:09:08 astro postgres[1574]: [4483-2] 2010-11-23 08:09:08 PSTLOCATION: exec_bind_message, postgres.c:1826
Nov 23 08:09:08 astro postgres[1574]: [4484-1] 2010-11-23 08:09:08 PSTLOG: 00000: execute <unnamed>: select advertisem0_.BASEUUID as uuid36_, advertisem0_1_.creationDate as creation2_36_, advertisem0_1_.depth as depth36_, advertisem0_1_.leftLimit as leftLimit36_, advertisem0_1_.modifiedDate as modified5_36_, advertisem0_1_.parent_uuid as parent6_36_, advertisem0_1_.rightLimit as rightLimit36_, advertisem0_1_.rootuuid as rootuuid36_, advertisem0_1_.text as text36_, advertisem0_1_.version as version36_, advertisem0_.aceScore as aceScore37_, advertisem0_.advertisementAgency_id as adverti27_37_, advertisem0_.PARENT_UUID as PARENT28_37_, advertisem0_.advertisementCompany_id as adverti29_37_, advertisem0_.advertisementMedia_id as adverti30_37_, advertisem0_.advertisementProduct_id as adverti31_37_, advertisem0_.advertisementStatus as advertis2_37_, advertisem0_.airDate as airDate37_, advertisem0_.attention as attention37_, advertisem0_.classic as classic37_, advertisem0_.country as country37_, advertisem0_.descri
Nov 23 08:09:08 astro postgres[1574]: [4484-2] desire37_, advertisem0_.hasBrandAssociation as hasBrand9_37_, advertisem0_.information as informa10_37_, advertisem0_.innovation as innovation37_, advertisem0_.language as language37_, advertisem0_.length as length37_, advertisem0_.liking as liking37_, advertisem0_.location as location37_, advertisem0_.numberOfRespondents as numberO16_37_, advertisem0_.partner_id as partner32_37_, advertisem0_.partnerId as partnerId37_, advertisem0_.persuasion as persuasion37_, advertisem0_.preCalcStatus as preCalc19_37_, advertisem0_.publicAd as publicAd37_, advertisem0_.readyToReportDate as readyTo21_37_, advertisem0_.relevance as relevance37_, advertisem0_.tagline as tagline37_, advertisem0_.title as title37_, advertisem0_.watchability as watchab25_37_ from ADVERTISEMENT_HIERARCHY advertisem0_ inner join AdvertisementHierarchyMetadata advertisem0_1_ on advertisem0_.BASEUUID=advertisem0_1_.uuid where advertisem0_.BASEUUID=$1 limit $2
Nov 23 08:09:08 astro postgres[1574]: [4484-3] 2010-11-23 08:09:08 PSTDETAIL: parameters: $1 = 'e9482a0c-611d-4439-866f-8c11972ec6cc', $2 = '2'
Nov 23 08:09:08 astro postgres[1574]: [4484-4] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:1972
Nov 23 08:09:08 astro postgres[1574]: [4485-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.138 ms
Nov 23 08:09:08 astro postgres[1574]: [4485-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:2043
Nov 23 08:09:08 astro postgres[1574]: [4486-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.039 ms
Nov 23 08:09:08 astro postgres[1574]: [4486-2] 2010-11-23 08:09:08 PSTLOCATION: exec_parse_message, postgres.c:1409
Nov 23 08:09:08 astro postgres[1574]: [4487-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.022 ms
Nov 23 08:09:08 astro postgres[1574]: [4487-2] 2010-11-23 08:09:08 PSTLOCATION: exec_bind_message, postgres.c:1826
Nov 23 08:09:08 astro postgres[1574]: [4488-1] 2010-11-23 08:09:08 PSTLOG: 00000: execute <unnamed>: SELECT current_timestamp
Nov 23 08:09:08 astro postgres[1574]: [4488-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:1972
Nov 23 08:09:08 astro postgres[1574]: [4489-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.062 ms
Nov 23 08:09:08 astro postgres[1574]: [4489-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:2043
Nov 23 08:09:08 astro postgres[1574]: [4490-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.248 ms
Nov 23 08:09:08 astro postgres[1574]: [4490-2] 2010-11-23 08:09:08 PSTLOCATION: exec_parse_message, postgres.c:1409
Nov 23 08:09:08 astro postgres[1574]: [4491-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.277 ms
Nov 23 08:09:08 astro postgres[1574]: [4491-2] 2010-11-23 08:09:08 PSTLOCATION: exec_bind_message, postgres.c:1826
Nov 23 08:09:08 astro postgres[1574]: [4492-1] 2010-11-23 08:09:08 PSTLOG: 00000: execute <unnamed>: update Advertisement set creationDate=$1, modifiedDate=$2, uuid=$3, version=$4, aceScore=$5, advertisementAgency_id=$6, advertisementBrand_id=$7, advertisementCompany_id=$8, advertisementMedia_id=$9, advertisementProduct_id=$10, advertisementStatus=$11, airDate=$12, attention=$13, classic=$14, country=$15, covey_id=$16, description=$17, desire=$18, hasBrandAssociation=$19, information=$20, innovation=$21, intender_id=$22, language=$23, length=$24, liking=$25, location=$26, numberOfRespondents=$27, partner_id=$28, partnerId=$29, persuasion=$30, preCalcStatus=$31, publicAd=$32, readyToReportDate=$33, relevance=$34, tagline=$35, title=$36, watchability=$37 where id=$38 and version=$39
Nov 23 08:09:08 astro postgres[1574]: [4492-2] 2010-11-23 08:09:08 PSTDETAIL: parameters: $1 = '2010-11-08 13:01:15.862', $2 = '2010-11-23 08:09:08.445', $3 = 'e9482a0c-611d-4439-866f-8c11972ec6cc', $4 = '10', $5 = '478.20976244039423', $6 = '150522026', $7 = '103494509', $8 = '134239040', $9 = '1', $10 = '6', $11 = '2', $12 = '2010-11-04 00:00:00', $13 = '625.712171811948', $14 = 'f', $15 = 'US', $16 = NULL, $17 = 'A group of men are at a bar. Man I got this round. He turns to walk toward the bar and performs various football actions as the M-Annc calls them. He finally is able to get to the bar and order. M-Annc states to call your own audible for a chance to win a trip to the hottest party in Dallas. Text: [BUD LIGHT HOTEL DALLAS] Go to ESPN.com search Bud Light.', $18 = '485.55699172583746', $19 = 't', $20 = '482.57421707217497', $21 = '551.76823352267138', $22 = '145734000', $23 = 'en', $24 = '30', $25 = '609.77250584759156', $26 = '2535489.flv', $27 = '622', $28 = '3', $29 = '2535489', $30 = '530.1470
Nov 23 08:09:08 astro postgres[1574]: [4492-3] '2010-11-08 18:59:33.362', $34 = '493.60195519423928', $35 = '', $36 = 'Bud Light Hotel Dallas', $37 = '556.90699953369278', $38 = '9914', $39 = '9'
Nov 23 08:09:08 astro postgres[1574]: [4492-4] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:1972
Nov 23 08:09:08 astro postgres[1574]: [4493-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.840 ms
Nov 23 08:09:08 astro postgres[1574]: [4493-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:2043
Nov 23 08:09:08 astro postgres[1156]: [1184454-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 36.975 ms
Nov 23 08:09:08 astro postgres[1156]: [1184454-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:2043
Nov 23 08:09:08 astro postgres[1574]: [4494-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.038 ms
Nov 23 08:09:08 astro postgres[1574]: [4494-2] 2010-11-23 08:09:08 PSTLOCATION: exec_parse_message, postgres.c:1409
Nov 23 08:09:08 astro postgres[1574]: [4495-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.018 ms
Nov 23 08:09:08 astro postgres[1574]: [4495-2] 2010-11-23 08:09:08 PSTLOCATION: exec_bind_message, postgres.c:1826
Nov 23 08:09:08 astro postgres[1574]: [4496-1] 2010-11-23 08:09:08 PSTLOG: 00000: execute <unnamed>: SELECT current_timestamp
Nov 23 08:09:08 astro postgres[1574]: [4496-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:1972
Nov 23 08:09:08 astro postgres[1574]: [4497-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.058 ms
Nov 23 08:09:08 astro postgres[1574]: [4497-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:2043
Nov 23 08:09:08 astro postgres[1574]: [4498-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.266 ms
Nov 23 08:09:08 astro postgres[1574]: [4498-2] 2010-11-23 08:09:08 PSTLOCATION: exec_parse_message, postgres.c:1409
Nov 23 08:09:08 astro postgres[1574]: [4499-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.181 ms
Nov 23 08:09:08 astro postgres[1574]: [4499-2] 2010-11-23 08:09:08 PSTLOCATION: exec_bind_message, postgres.c:1826
Nov 23 08:09:08 astro postgres[1574]: [4500-1] 2010-11-23 08:09:08 PSTLOG: 00000: execute <unnamed>: select advertisem0_.id as id23_, advertisem0_.creationDate as creation2_23_, advertisem0_.modifiedDate as modified3_23_, advertisem0_.uuid as uuid23_, advertisem0_.version as version23_, advertisem0_.aceScore as aceScore23_, advertisem0_.advertisementAgency_id as adverti31_23_, advertisem0_.advertisementBrand_id as adverti32_23_, advertisem0_.advertisementCompany_id as adverti33_23_, advertisem0_.advertisementMedia_id as adverti34_23_, advertisem0_.advertisementProduct_id as adverti35_23_, advertisem0_.advertisementStatus as advertis7_23_, advertisem0_.airDate as airDate23_, advertisem0_.attention as attention23_, advertisem0_.classic as classic23_, advertisem0_.country as country23_, advertisem0_.covey_id as covey36_23_, advertisem0_.description as descrip12_23_, advertisem0_.desire as desire23_, advertisem0_.hasBrandAssociation as hasBran14_23_, advertisem0_.information as informa15_23_, advertisem0_.innov
Nov 23 08:09:08 astro postgres[1574]: [4500-2] as intender37_23_, advertisem0_.language as language23_, advertisem0_.length as length23_, advertisem0_.liking as liking23_, advertisem0_.location as location23_, advertisem0_.numberOfRespondents as numberO21_23_, advertisem0_.partner_id as partner38_23_, advertisem0_.partnerId as partnerId23_, advertisem0_.persuasion as persuasion23_, advertisem0_.preCalcStatus as preCalc24_23_, advertisem0_.publicAd as publicAd23_, advertisem0_.readyToReportDate as readyTo26_23_, advertisem0_.relevance as relevance23_, advertisem0_.tagline as tagline23_, advertisem0_.title as title23_, advertisem0_.watchability as watchab30_23_ from Advertisement advertisem0_ where advertisem0_.uuid=$1 limit $2
Nov 23 08:09:08 astro postgres[1574]: [4500-3] 2010-11-23 08:09:08 PSTDETAIL: parameters: $1 = 'e9482a0c-611d-4439-866f-8c11972ec6cc', $2 = '2'
Nov 23 08:09:08 astro postgres[1574]: [4500-4] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:1972
Nov 23 08:09:08 astro postgres[1574]: [4501-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.216 ms
Nov 23 08:09:08 astro postgres[1574]: [4501-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:2043
Nov 23 08:09:08 astro postgres[1573]: [16-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.354 ms
Nov 23 08:09:08 astro postgres[1573]: [16-2] 2010-11-23 08:09:08 PSTLOCATION: exec_parse_message, postgres.c:1409
Nov 23 08:09:08 astro postgres[1573]: [17-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.026 ms
Nov 23 08:09:08 astro postgres[1573]: [17-2] 2010-11-23 08:09:08 PSTLOCATION: exec_bind_message, postgres.c:1826
Nov 23 08:09:08 astro postgres[1573]: [18-1] 2010-11-23 08:09:08 PSTLOG: 00000: execute <unnamed>: SELECT gid FROM pg_prepared_xacts
Nov 23 08:09:08 astro postgres[1573]: [18-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:1972
Nov 23 08:09:08 astro postgres[1573]: [19-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.078 ms
Nov 23 08:09:08 astro postgres[1573]: [19-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:2043
Nov 23 08:09:08 astro postgres[1573]: [20-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.043 ms
Nov 23 08:09:08 astro postgres[1573]: [20-2] 2010-11-23 08:09:08 PSTLOCATION: exec_parse_message, postgres.c:1409
Nov 23 08:09:08 astro postgres[1573]: [21-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.005 ms
Nov 23 08:09:08 astro postgres[1573]: [21-2] 2010-11-23 08:09:08 PSTLOCATION: exec_bind_message, postgres.c:1826
Nov 23 08:09:08 astro postgres[1573]: [22-1] 2010-11-23 08:09:08 PSTLOG: 00000: execute <unnamed>: ROLLBACK PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjE2OTgwMDAwMg==_MTkyLjE2OC4xNjguMjUwLnRtNTM2OTk='
Nov 23 08:09:08 astro postgres[1573]: [22-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:1972
Nov 23 08:09:08 astro postgres[1573]: [23-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 16.766 ms
Nov 23 08:09:08 astro postgres[1573]: [23-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:2043
Nov 23 08:09:08 astro postgres[1587]: [12-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.261 ms
Nov 23 08:09:08 astro postgres[1587]: [12-2] 2010-11-23 08:09:08 PSTLOCATION: exec_parse_message, postgres.c:1409
Nov 23 08:09:08 astro postgres[1587]: [13-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.025 ms
Nov 23 08:09:08 astro postgres[1587]: [13-2] 2010-11-23 08:09:08 PSTLOCATION: exec_bind_message, postgres.c:1826
Nov 23 08:09:08 astro postgres[1587]: [14-1] 2010-11-23 08:09:08 PSTLOG: 00000: execute <unnamed>: SELECT gid FROM pg_prepared_xacts
Nov 23 08:09:08 astro postgres[1587]: [14-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:1972
Nov 23 08:09:08 astro postgres[1587]: [15-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.060 ms
Nov 23 08:09:08 astro postgres[1587]: [15-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:2043
Nov 23 08:09:08 astro postgres[1602]: [8-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.331 ms
Nov 23 08:09:08 astro postgres[1602]: [8-2] 2010-11-23 08:09:08 PSTLOCATION: exec_parse_message, postgres.c:1409
Nov 23 08:09:08 astro postgres[1602]: [9-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.025 ms
Nov 23 08:09:08 astro postgres[1602]: [9-2] 2010-11-23 08:09:08 PSTLOCATION: exec_bind_message, postgres.c:1826
Nov 23 08:09:08 astro postgres[1602]: [10-1] 2010-11-23 08:09:08 PSTLOG: 00000: execute <unnamed>: SELECT gid FROM pg_prepared_xacts
Nov 23 08:09:08 astro postgres[1602]: [10-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:1972
Nov 23 08:09:08 astro postgres[1602]: [11-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.059 ms
Nov 23 08:09:08 astro postgres[1602]: [11-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:2043
Nov 23 08:09:08 astro postgres[12536]: [2-1] 2010-11-23 08:09:08 PSTLOG: 00000: connection received: host=192.168.168.250 port=52039
Nov 23 08:09:08 astro postgres[12536]: [2-2] 2010-11-23 08:09:08 PSTLOCATION: BackendInitialize, postmaster.c:3409
Nov 23 08:09:08 astro postgres[1156]: [1184455-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.037 ms
Nov 23 08:09:08 astro postgres[1156]: [1184455-2] 2010-11-23 08:09:08 PSTLOCATION: exec_parse_message, postgres.c:1409
Nov 23 08:09:08 astro postgres[1156]: [1184456-1] 2010-11-23 08:09:08 PSTLOG: 00000: duration: 0.006 ms
Nov 23 08:09:08 astro postgres[1156]: [1184456-2] 2010-11-23 08:09:08 PSTLOCATION: exec_bind_message, postgres.c:1826
Nov 23 08:09:08 astro postgres[1156]: [1184457-1] 2010-11-23 08:09:08 PSTLOG: 00000: execute <unnamed>: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjE2OTgwMDAwMg==_MTkyLjE2OC4xNjguMjUwLnRtNTM2OTk='
Nov 23 08:09:08 astro postgres[1156]: [1184457-2] 2010-11-23 08:09:08 PSTLOCATION: exec_execute_message, postgres.c:1972
Nov 23 08:09:08 astro postgres[1156]: [1184458-1] 2010-11-23 08:09:08 PSTERROR: 42704: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjE2OTgwMDAwMg==_MTkyLjE2OC4xNjguMjUwLnRtNTM2OTk=" does not exist
Nov 23 08:09:08 astro postgres[1156]: [1184458-2] 2010-11-23 08:09:08 PSTLOCATION: LockGXact, twophase.c:454
Nov 23 08:09:08 astro postgres[1156]: [1184458-3] 2010-11-23 08:09:08 PSTSTATEMENT: COMMIT PREPARED '1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjE2OTgwMDAwMg==_MTkyLjE2OC4xNjguMjUwLnRtNTM2OTk='
And here's the output from tm.out:
10-11-23 05:46:44,891 [main] arcDataSource: refreshed XAResource
10-11-23 05:46:44,903 [main] surveyDataSource: refreshed XAResource
10-11-23 05:46:45,226 [main] smoothieDataSource: refreshed XAResource
10-11-23 05:46:45,392 [main] ssDataSource: refreshed XAResource
10-11-23 05:47:38,168 [main] Logfile closed: /opt/styx/tmp/styx_lucene/tmlog0.log
<snip>
10-11-23 08:08:43,507 [main] Logfile closed: /opt/styx/tmp/styx_lucene/tmlog213.log
10-11-23 08:09:08,630 [main] XA resource 'arcDataSource': commit for XID '3139322E3136382E3136382E3235302E746D32313639383030303032:3139322E3136382E3136382E3235302E746D3533363939' raised -3: the XA resource detected an internal error
org.postgresql.xa.PGXAException: Error committing prepared transaction
at org.postgresql.xa.PGXAConnection.commitPrepared(PGXAConnection.java:497)
at org.postgresql.xa.PGXAConnection.commit(PGXAConnection.java:420)
at com.atomikos.datasource.xa.XAResourceTransaction.commit(XAResourceTransaction.java:999)
at com.atomikos.icatch.imp.CommitMessage.send(CommitMessage.java:94)
at com.atomikos.icatch.imp.PropagationMessage.submit(PropagationMessage.java:86)
at com.atomikos.icatch.imp.Propagator$PropagatorThread.run(Propagator.java:62)
at com.atomikos.icatch.imp.Propagator.submitPropagationMessage(Propagator.java:41)
at com.atomikos.icatch.imp.CoordinatorStateHandler.commit(CoordinatorStateHandler.java:661)
at com.atomikos.icatch.imp.IndoubtStateHandler.commit(IndoubtStateHandler.java:225)
at com.atomikos.icatch.imp.CoordinatorImp.commit(CoordinatorImp.java:828)
at com.atomikos.icatch.imp.CoordinatorImp.terminate(CoordinatorImp.java:1127)
at com.atomikos.icatch.imp.CompositeTerminatorImp.commit(CompositeTerminatorImp.java:151)
at com.atomikos.icatch.jta.TransactionImp.commit(TransactionImp.java:317)
at com.atomikos.icatch.jta.TransactionManagerImp.commit(TransactionManagerImp.java:613)
at com.atomikos.icatch.jta.UserTransactionManager.commit(UserTransactionManager.java:149)
at org.hibernate.engine.transaction.Isolater$JtaDelegate.delegateWork(Isolater.java:137)
at org.hibernate.engine.transaction.Isolater.doIsolatedWork(Isolater.java:64)
at org.hibernate.engine.TransactionHelper.doWorkInNewTransaction(TransactionHelper.java:74)
at org.hibernate.id.enhanced.TableGenerator$1.getNextValue(TableGenerator.java:429)
at org.hibernate.id.enhanced.OptimizerFactory$PooledOptimizer.generate(OptimizerFactory.java:276)
at org.hibernate.id.enhanced.TableGenerator.generate(TableGenerator.java:426)
at org.hibernate.event.def.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:122)
at org.hibernate.ejb.event.EJB3PersistEventListener.saveWithGeneratedId(EJB3PersistEventListener.java:49)
at org.hibernate.event.def.DefaultPersistEventListener.entityIsTransient(DefaultPersistEventListener.java:154)
at org.hibernate.event.def.DefaultPersistEventListener.onPersist(DefaultPersistEventListener.java:110)
at org.hibernate.event.def.DefaultPersistEventListener.onPersist(DefaultPersistEventListener.java:61)
at org.hibernate.impl.SessionImpl.firePersist(SessionImpl.java:645)
at org.hibernate.impl.SessionImpl.persist(SessionImpl.java:619)
at org.hibernate.impl.SessionImpl.persist(SessionImpl.java:623)
at org.hibernate.ejb.AbstractEntityManagerImpl.persist(AbstractEntityManagerImpl.java:220)
at sun.reflect.GeneratedMethodAccessor180.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler.invoke(ExtendedEntityManagerCreator.java:365)
at $Proxy79.persist(Unknown Source)
at sun.reflect.GeneratedMethodAccessor180.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:240)
at $Proxy53.persist(Unknown Source)
at com.adratingco.daos.jpa.JpaAbstractDao.save(JpaAbstractDao.java:134)
at sun.reflect.GeneratedMethodAccessor184.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
at $Proxy65.save(Unknown Source)
at com.adratingco.riverstyx.roadies.NormCalculatorRoadie.computeNorm(NormCalculatorRoadie.java:145)
at com.adratingco.riverstyx.services.NormService.calculateAdvertisementNorm(NormService.java:53)
at sun.reflect.GeneratedMethodAccessor296.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
at $Proxy81.calculateAdvertisementNorm(Unknown Source)
at com.adratingco.riverstyx.json.apps.PreCalculator.preCalcAd(PreCalculator.java:38)
at com.adratingco.riverstyx.json.apps.PreCalculator$$FastClassByCGLIB$$156b1558.invoke(<generated>)
at net.sf.cglib.proxy.MethodProxy.invoke(MethodProxy.java:191)
at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:617)
at com.adratingco.riverstyx.json.apps.PreCalculator$$EnhancerByCGLIB$$ba6b594f.preCalcAd(<generated>)
at com.adratingco.riverstyx.json.apps.PreCalculator.main(PreCalculator.java:386)
Caused by: org.postgresql.util.PSQLException: ERROR: prepared transaction with identifier "1096044365_MTkyLjE2OC4xNjguMjUwLnRtMjE2OTgwMDAwMg==_MTkyLjE2OC4xNjguMjUwLnRtNTM2OTk=" does not exist
at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2102)
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1835)
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:374)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:302)
at org.postgresql.xa.PGXAConnection.commitPrepared(PGXAConnection.java:487)
... 68 more
10-11-23 08:09:08,631 [main] Unexpected error in commit
com.atomikos.icatch.SysException: XA resource 'arcDataSource': commit for XID '3139322E3136382E3136382E3235302E746D32313639383030303032:3139322E3136382E3136382E3235302E746D3533363939' raised -3: the XA resource detected an internal error
at com.atomikos.datasource.xa.XAResourceTransaction.commit(XAResourceTransaction.java:1039)
at com.atomikos.icatch.imp.CommitMessage.send(CommitMessage.java:94)
at com.atomikos.icatch.imp.PropagationMessage.submit(PropagationMessage.java:86)
at com.atomikos.icatch.imp.Propagator$PropagatorThread.run(Propagator.java:62)
at com.atomikos.icatch.imp.Propagator.submitPropagationMessage(Propagator.java:41)
at com.atomikos.icatch.imp.CoordinatorStateHandler.commit(CoordinatorStateHandler.java:661)
at com.atomikos.icatch.imp.IndoubtStateHandler.commit(IndoubtStateHandler.java:225)
at com.atomikos.icatch.imp.CoordinatorImp.commit(CoordinatorImp.java:828)
at com.atomikos.icatch.imp.CoordinatorImp.terminate(CoordinatorImp.java:1127)
at com.atomikos.icatch.imp.CompositeTerminatorImp.commit(CompositeTerminatorImp.java:151)
at com.atomikos.icatch.jta.TransactionImp.commit(TransactionImp.java:317)
at com.atomikos.icatch.jta.TransactionManagerImp.commit(TransactionManagerImp.java:613)
at com.atomikos.icatch.jta.UserTransactionManager.commit(UserTransactionManager.java:149)
at org.hibernate.engine.transaction.Isolater$JtaDelegate.delegateWork(Isolater.java:137)
at org.hibernate.engine.transaction.Isolater.doIsolatedWork(Isolater.java:64)
at org.hibernate.engine.TransactionHelper.doWorkInNewTransaction(TransactionHelper.java:74)
at org.hibernate.id.enhanced.TableGenerator$1.getNextValue(TableGenerator.java:429)
at org.hibernate.id.enhanced.OptimizerFactory$PooledOptimizer.generate(OptimizerFactory.java:276)
at org.hibernate.id.enhanced.TableGenerator.generate(TableGenerator.java:426)
at org.hibernate.event.def.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:122)
at org.hibernate.ejb.event.EJB3PersistEventListener.saveWithGeneratedId(EJB3PersistEventListener.java:49)
at org.hibernate.event.def.DefaultPersistEventListener.entityIsTransient(DefaultPersistEventListener.java:154)
at org.hibernate.event.def.DefaultPersistEventListener.onPersist(DefaultPersistEventListener.java:110)
at org.hibernate.event.def.DefaultPersistEventListener.onPersist(DefaultPersistEventListener.java:61)
at org.hibernate.impl.SessionImpl.firePersist(SessionImpl.java:645)
at org.hibernate.impl.SessionImpl.persist(SessionImpl.java:619)
at org.hibernate.impl.SessionImpl.persist(SessionImpl.java:623)
at org.hibernate.ejb.AbstractEntityManagerImpl.persist(AbstractEntityManagerImpl.java:220)
at sun.reflect.GeneratedMethodAccessor180.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler.invoke(ExtendedEntityManagerCreator.java:365)
at $Proxy79.persist(Unknown Source)
at sun.reflect.GeneratedMethodAccessor180.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:240)
at $Proxy53.persist(Unknown Source)
at com.adratingco.daos.jpa.JpaAbstractDao.save(JpaAbstractDao.java:134)
at sun.reflect.GeneratedMethodAccessor184.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
at $Proxy65.save(Unknown Source)
at com.adratingco.riverstyx.roadies.NormCalculatorRoadie.computeNorm(NormCalculatorRoadie.java:145)
at com.adratingco.riverstyx.services.NormService.calculateAdvertisementNorm(NormService.java:53)
at sun.reflect.GeneratedMethodAccessor296.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
at $Proxy81.calculateAdvertisementNorm(Unknown Source)
at com.adratingco.riverstyx.json.apps.PreCalculator.preCalcAd(PreCalculator.java:38)
at com.adratingco.riverstyx.json.apps.PreCalculator$$FastClassByCGLIB$$156b1558.invoke(<generated>)
at net.sf.cglib.proxy.MethodProxy.invoke(MethodProxy.java:191)
at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:617)
at com.adratingco.riverstyx.json.apps.PreCalculator$$EnhancerByCGLIB$$ba6b594f.preCalcAd(<generated>)
at com.adratingco.riverstyx.json.apps.PreCalculator.main(PreCalculator.java:386)
The errors in postgres and atomikos logs repeat indefinitely after that. If you guys want full logs, any additional information, config changes or anything else, please let me know.
-- Tim
Oh, I'm going to be out of town over the long weekend, leaving today and returning 11/30. Please don't think I've disappeared. This is a top issue for us and I would really like to continue pursuing it.
Hello,
I wanted to check in on how things were going with this issue. If I'm reading the logs posted above correctly, it looks like PostgreSQL is receiving the initial prepare. Some work is done inside the transaction and for whatever reason Atomikos triggers a rollback. It's after this rollback that Atomikos seems to drop into the error pattern of continuously trying to prepare the transaction that was rolled back. This retry continues, even though PostgreSQL throws an error every time.
In response to Simon's question, it seems Atomikos is the one getting out of sync. Regardless of which system is responsible for getting out of sync, this points out the weakness of the unbounded retry policy hard coded in Atomikos libraries. It would be nice to at least be able to configure in a retry limit to workaround this error in our currently deployed production systems.
Please let us know if there is anything we can do with a limited support contract to get this fixed quickly.
Thank you,
-- Tim
I wanted to check in on how things were going with this issue. If I'm reading the logs posted above correctly, it looks like PostgreSQL is receiving the initial prepare. Some work is done inside the transaction and for whatever reason Atomikos triggers a rollback. It's after this rollback that Atomikos seems to drop into the error pattern of continuously trying to prepare the transaction that was rolled back. This retry continues, even though PostgreSQL throws an error every time.
In response to Simon's question, it seems Atomikos is the one getting out of sync. Regardless of which system is responsible for getting out of sync, this points out the weakness of the unbounded retry policy hard coded in Atomikos libraries. It would be nice to at least be able to configure in a retry limit to workaround this error in our currently deployed production systems.
Please let us know if there is anything we can do with a limited support contract to get this fixed quickly.
Thank you,
-- Tim
Tim,
We're checking what can be done and will let you know once we have something concrete.
Thanks
We're checking what can be done and will let you know once we have something concrete.
Thanks
Guy Pardon
Monday, December 06, 2010
Monday, December 06, 2010
Hi Guy,
Thanks again for the reply. Unfortunately we've made the painful decision to remove Atomikos dependencies from our systems. When we first started out JTA was a good way for us to spread our data around. That initial system was more of your typical OLTP style application. As our data requirements have grown, we've brought in more and more big data and OLAP style requirements. Unfortunately, it seems Atomikos is not a good fit for the types of long running transactional operations we're facing now.
Once again, thanks for helping us get this far.
Cheers,
-- Tim
Thanks again for the reply. Unfortunately we've made the painful decision to remove Atomikos dependencies from our systems. When we first started out JTA was a good way for us to spread our data around. That initial system was more of your typical OLTP style application. As our data requirements have grown, we've brought in more and more big data and OLAP style requirements. Unfortunately, it seems Atomikos is not a good fit for the types of long running transactional operations we're facing now.
Once again, thanks for helping us get this far.
Cheers,
-- Tim
Thanks for the update; you might want to check this: http://www.atomikos.com/Publications/TryConfirmCancel
Best
Best
Guy Pardon
Friday, December 10, 2010
Friday, December 10, 2010
Other recent topics