interesting exception in 3.0

classic Classic list List threaded Threaded
13 messages Options
Reply | Threaded
Open this post in threaded view
|

interesting exception in 3.0

François Schiettecatte
Hi

I grabbed the latest, greatest release of 3.0 from :

        http://people.apache.org/builds/ibatis/ibatis-3-core/ibatis-core-3.0-bundle.zip

and am now getting an exception from time to time, but I was not getting it with the previous 3.0 beta release (240). I was wondering if there had been any change in the code which deals with connections and pool between those two releases. What it looks like to me is that connections are not being returned to the pool after I close the SqlSession. I have mysql set to timeout idle connections after 60 seconds and the connection pool to time out idle connections after 50 seconds. Again this was not an issue in 240.

Any suggestions?

Cheers

François


2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:8)
2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:61)
2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:53)
2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:38)
2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.sql.IBatis.selectObject(IBatis.java:554)
2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.dictionaries.Category.fromCategoryName(Category.java:118)
2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.ItemCategory.<init>(ItemCategory.java:201)
2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.ItemCategory.<init>(ItemCategory.java:227)
2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.Item.addItemCategory(Item.java:2182)
2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.processors.FeedProcessor.processEntryCategories(FeedProcessor.java:2494)
2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.processors.FeedProcessor.process(FeedProcessor.java:823)
2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.crawl(Worker.java:1313)
2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.crawlSourceKey(Worker.java:681)
2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.run(Worker.java:591)
2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.lang.Thread.run(Thread.java:619)
2010-05-01 01:54:20,609 [pool-1-thread-1] WARN  com.poplar.crawler.Worker - Failed to crawl the source key: 'C01240E19154BE7BDA3703F726D5A68190D4A540', exception: 'org.apache.ibatis.exceptions.IbatisException:
### Error querying database.  Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 104,024 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.
### The error may involve dictionaries.Category.selectObjectByCategoryName-Inline
### The error occurred while setting parameters
### Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 104,024 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.'.


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: interesting exception in 3.0

Clinton Begin
The only code changes related to that were with managed transactions.
Which transacion manager are you using?  (JDBC or MANAGED)?

Cheers,
Clinton

2010/5/1 François Schiettecatte <[hidden email]>:

> Hi
>
> I grabbed the latest, greatest release of 3.0 from :
>
>        http://people.apache.org/builds/ibatis/ibatis-3-core/ibatis-core-3.0-bundle.zip
>
> and am now getting an exception from time to time, but I was not getting it with the previous 3.0 beta release (240). I was wondering if there had been any change in the code which deals with connections and pool between those two releases. What it looks like to me is that connections are not being returned to the pool after I close the SqlSession. I have mysql set to timeout idle connections after 60 seconds and the connection pool to time out idle connections after 50 seconds. Again this was not an issue in 240.
>
> Any suggestions?
>
> Cheers
>
> François
>
>
> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:8)
> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:61)
> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:53)
> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:38)
> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.sql.IBatis.selectObject(IBatis.java:554)
> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.dictionaries.Category.fromCategoryName(Category.java:118)
> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.ItemCategory.<init>(ItemCategory.java:201)
> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.ItemCategory.<init>(ItemCategory.java:227)
> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.Item.addItemCategory(Item.java:2182)
> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.processors.FeedProcessor.processEntryCategories(FeedProcessor.java:2494)
> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.processors.FeedProcessor.process(FeedProcessor.java:823)
> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.crawl(Worker.java:1313)
> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.crawlSourceKey(Worker.java:681)
> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.run(Worker.java:591)
> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.lang.Thread.run(Thread.java:619)
> 2010-05-01 01:54:20,609 [pool-1-thread-1] WARN  com.poplar.crawler.Worker - Failed to crawl the source key: 'C01240E19154BE7BDA3703F726D5A68190D4A540', exception: 'org.apache.ibatis.exceptions.IbatisException:
> ### Error querying database.  Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
>
> The last packet successfully received from the server was 104,024 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.
> ### The error may involve dictionaries.Category.selectObjectByCategoryName-Inline
> ### The error occurred while setting parameters
> ### Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
>
> The last packet successfully received from the server was 104,024 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.'.
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: interesting exception in 3.0

François Schiettecatte
I am using JDBC, with C3P0 as my data source.

Cheers
François

On May 1, 2010, at 4:14 PM, Clinton Begin wrote:

> The only code changes related to that were with managed transactions.
> Which transacion manager are you using?  (JDBC or MANAGED)?
>
> Cheers,
> Clinton
>
> 2010/5/1 François Schiettecatte <[hidden email]>:
>> Hi
>>
>> I grabbed the latest, greatest release of 3.0 from :
>>
>>        http://people.apache.org/builds/ibatis/ibatis-3-core/ibatis-core-3.0-bundle.zip
>>
>> and am now getting an exception from time to time, but I was not getting it with the previous 3.0 beta release (240). I was wondering if there had been any change in the code which deals with connections and pool between those two releases. What it looks like to me is that connections are not being returned to the pool after I close the SqlSession. I have mysql set to timeout idle connections after 60 seconds and the connection pool to time out idle connections after 50 seconds. Again this was not an issue in 240.
>>
>> Any suggestions?
>>
>> Cheers
>>
>> François
>>
>>
>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:8)
>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:61)
>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:53)
>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:38)
>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.sql.IBatis.selectObject(IBatis.java:554)
>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.dictionaries.Category.fromCategoryName(Category.java:118)
>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.ItemCategory.<init>(ItemCategory.java:201)
>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.ItemCategory.<init>(ItemCategory.java:227)
>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.Item.addItemCategory(Item.java:2182)
>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.processors.FeedProcessor.processEntryCategories(FeedProcessor.java:2494)
>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.processors.FeedProcessor.process(FeedProcessor.java:823)
>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.crawl(Worker.java:1313)
>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.crawlSourceKey(Worker.java:681)
>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.run(Worker.java:591)
>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.lang.Thread.run(Thread.java:619)
>> 2010-05-01 01:54:20,609 [pool-1-thread-1] WARN  com.poplar.crawler.Worker - Failed to crawl the source key: 'C01240E19154BE7BDA3703F726D5A68190D4A540', exception: 'org.apache.ibatis.exceptions.IbatisException:
>> ### Error querying database.  Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
>>
>> The last packet successfully received from the server was 104,024 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.
>> ### The error may involve dictionaries.Category.selectObjectByCategoryName-Inline
>> ### The error occurred while setting parameters
>> ### Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
>>
>> The last packet successfully received from the server was 104,024 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.'.
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [hidden email]
>> For additional commands, e-mail: [hidden email]
>>
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: interesting exception in 3.0

Clinton Begin
Then no, I don't believe there have been any changes related to
connections or transactions between those versions.  You can have a
look at the change log if you like:

https://issues.apache.org/jira/secure/BrowseProject.jspa?id=10601&subset=-1

Or the subversion history as well.

Clinton

2010/5/1 François Schiettecatte <[hidden email]>:

> I am using JDBC, with C3P0 as my data source.
>
> Cheers
> François
>
> On May 1, 2010, at 4:14 PM, Clinton Begin wrote:
>
>> The only code changes related to that were with managed transactions.
>> Which transacion manager are you using?  (JDBC or MANAGED)?
>>
>> Cheers,
>> Clinton
>>
>> 2010/5/1 François Schiettecatte <[hidden email]>:
>>> Hi
>>>
>>> I grabbed the latest, greatest release of 3.0 from :
>>>
>>>        http://people.apache.org/builds/ibatis/ibatis-3-core/ibatis-core-3.0-bundle.zip
>>>
>>> and am now getting an exception from time to time, but I was not getting it with the previous 3.0 beta release (240). I was wondering if there had been any change in the code which deals with connections and pool between those two releases. What it looks like to me is that connections are not being returned to the pool after I close the SqlSession. I have mysql set to timeout idle connections after 60 seconds and the connection pool to time out idle connections after 50 seconds. Again this was not an issue in 240.
>>>
>>> Any suggestions?
>>>
>>> Cheers
>>>
>>> François
>>>
>>>
>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:8)
>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:61)
>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:53)
>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:38)
>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.sql.IBatis.selectObject(IBatis.java:554)
>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.dictionaries.Category.fromCategoryName(Category.java:118)
>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.ItemCategory.<init>(ItemCategory.java:201)
>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.ItemCategory.<init>(ItemCategory.java:227)
>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.Item.addItemCategory(Item.java:2182)
>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.processors.FeedProcessor.processEntryCategories(FeedProcessor.java:2494)
>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.processors.FeedProcessor.process(FeedProcessor.java:823)
>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.crawl(Worker.java:1313)
>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.crawlSourceKey(Worker.java:681)
>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.run(Worker.java:591)
>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.lang.Thread.run(Thread.java:619)
>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] WARN  com.poplar.crawler.Worker - Failed to crawl the source key: 'C01240E19154BE7BDA3703F726D5A68190D4A540', exception: 'org.apache.ibatis.exceptions.IbatisException:
>>> ### Error querying database.  Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
>>>
>>> The last packet successfully received from the server was 104,024 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.
>>> ### The error may involve dictionaries.Category.selectObjectByCategoryName-Inline
>>> ### The error occurred while setting parameters
>>> ### Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
>>>
>>> The last packet successfully received from the server was 104,024 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.'.
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: [hidden email]
>>> For additional commands, e-mail: [hidden email]
>>>
>>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [hidden email]
>> For additional commands, e-mail: [hidden email]
>>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: interesting exception in 3.0

François Schiettecatte
Clinton

A little more information on this, I reverted back to 240 and the problem I reported did not occurs after a 24 hour run. I then went to the current release and the problem reappeared, everything else is the same, so there is an issue.

What it looks like is going on is that connections are not being put back into the connection pool after they are closed and so time out when they are subsequently used by iBatis.  MySQL is set to close connections after 60 seconds and the pool is set to close them after being idle for 50 seconds. Yet what I am seeing is that connections are being used quite some time after the last packets have been sent over the wire:

### Error querying database.  Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
The last packet successfully received from the server was 60,858 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.
### The error may involve dictionaries.Category.selectObjectByCategoryID-Inline
### The error occurred while setting parameters
### Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

What it feels like is that iBatis is hanging onto the connection and reusing it at a later time.

What do you need from me to track this down?

Cheers

François



On May 1, 2010, at 4:28 PM, Clinton Begin wrote:

> Then no, I don't believe there have been any changes related to
> connections or transactions between those versions.  You can have a
> look at the change log if you like:
>
> https://issues.apache.org/jira/secure/BrowseProject.jspa?id=10601&subset=-1
>
> Or the subversion history as well.
>
> Clinton
>
> 2010/5/1 François Schiettecatte <[hidden email]>:
>> I am using JDBC, with C3P0 as my data source.
>>
>> Cheers
>> François
>>
>> On May 1, 2010, at 4:14 PM, Clinton Begin wrote:
>>
>>> The only code changes related to that were with managed transactions.
>>> Which transacion manager are you using?  (JDBC or MANAGED)?
>>>
>>> Cheers,
>>> Clinton
>>>
>>> 2010/5/1 François Schiettecatte <[hidden email]>:
>>>> Hi
>>>>
>>>> I grabbed the latest, greatest release of 3.0 from :
>>>>
>>>>        http://people.apache.org/builds/ibatis/ibatis-3-core/ibatis-core-3.0-bundle.zip
>>>>
>>>> and am now getting an exception from time to time, but I was not getting it with the previous 3.0 beta release (240). I was wondering if there had been any change in the code which deals with connections and pool between those two releases. What it looks like to me is that connections are not being returned to the pool after I close the SqlSession. I have mysql set to timeout idle connections after 60 seconds and the connection pool to time out idle connections after 50 seconds. Again this was not an issue in 240.
>>>>
>>>> Any suggestions?
>>>>
>>>> Cheers
>>>>
>>>> François
>>>>
>>>>
>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:8)
>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:61)
>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:53)
>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:38)
>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.sql.IBatis.selectObject(IBatis.java:554)
>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.dictionaries.Category.fromCategoryName(Category.java:118)
>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.ItemCategory.<init>(ItemCategory.java:201)
>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.ItemCategory.<init>(ItemCategory.java:227)
>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.Item.addItemCategory(Item.java:2182)
>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.processors.FeedProcessor.processEntryCategories(FeedProcessor.java:2494)
>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.processors.FeedProcessor.process(FeedProcessor.java:823)
>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.crawl(Worker.java:1313)
>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.crawlSourceKey(Worker.java:681)
>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.run(Worker.java:591)
>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.lang.Thread.run(Thread.java:619)
>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] WARN  com.poplar.crawler.Worker - Failed to crawl the source key: 'C01240E19154BE7BDA3703F726D5A68190D4A540', exception: 'org.apache.ibatis.exceptions.IbatisException:
>>>> ### Error querying database.  Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
>>>>
>>>> The last packet successfully received from the server was 104,024 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.
>>>> ### The error may involve dictionaries.Category.selectObjectByCategoryName-Inline
>>>> ### The error occurred while setting parameters
>>>> ### Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
>>>>
>>>> The last packet successfully received from the server was 104,024 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.'.
>>>>
>>>>
>>>> ---------------------------------------------------------------------
>>>> To unsubscribe, e-mail: [hidden email]
>>>> For additional commands, e-mail: [hidden email]
>>>>
>>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: [hidden email]
>>> For additional commands, e-mail: [hidden email]
>>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [hidden email]
>> For additional commands, e-mail: [hidden email]
>>
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: interesting exception in 3.0

Clinton Begin
Two things to do:

* Create a JIRA ticket for this.  We'll continue conversation and
investigation there.

* Mount the source and step through one example transaction.  See if
you can verify that close isn't being called, and possibly why.

* Finally, out of curiosity, disable caching globally, and see if the
problem remains.

I did find one refactoring that is in this area.  I'll attempt to
recreate and verify this too.

Clinton

2010/5/5 François Schiettecatte <[hidden email]>:

> Clinton
>
> A little more information on this, I reverted back to 240 and the problem I reported did not occurs after a 24 hour run. I then went to the current release and the problem reappeared, everything else is the same, so there is an issue.
>
> What it looks like is going on is that connections are not being put back into the connection pool after they are closed and so time out when they are subsequently used by iBatis.  MySQL is set to close connections after 60 seconds and the pool is set to close them after being idle for 50 seconds. Yet what I am seeing is that connections are being used quite some time after the last packets have been sent over the wire:
>
> ### Error querying database.  Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> The last packet successfully received from the server was 60,858 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.
> ### The error may involve dictionaries.Category.selectObjectByCategoryID-Inline
> ### The error occurred while setting parameters
> ### Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
>
> What it feels like is that iBatis is hanging onto the connection and reusing it at a later time.
>
> What do you need from me to track this down?
>
> Cheers
>
> François
>
>
>
> On May 1, 2010, at 4:28 PM, Clinton Begin wrote:
>
>> Then no, I don't believe there have been any changes related to
>> connections or transactions between those versions.  You can have a
>> look at the change log if you like:
>>
>> https://issues.apache.org/jira/secure/BrowseProject.jspa?id=10601&subset=-1
>>
>> Or the subversion history as well.
>>
>> Clinton
>>
>> 2010/5/1 François Schiettecatte <[hidden email]>:
>>> I am using JDBC, with C3P0 as my data source.
>>>
>>> Cheers
>>> François
>>>
>>> On May 1, 2010, at 4:14 PM, Clinton Begin wrote:
>>>
>>>> The only code changes related to that were with managed transactions.
>>>> Which transacion manager are you using?  (JDBC or MANAGED)?
>>>>
>>>> Cheers,
>>>> Clinton
>>>>
>>>> 2010/5/1 François Schiettecatte <[hidden email]>:
>>>>> Hi
>>>>>
>>>>> I grabbed the latest, greatest release of 3.0 from :
>>>>>
>>>>>        http://people.apache.org/builds/ibatis/ibatis-3-core/ibatis-core-3.0-bundle.zip
>>>>>
>>>>> and am now getting an exception from time to time, but I was not getting it with the previous 3.0 beta release (240). I was wondering if there had been any change in the code which deals with connections and pool between those two releases. What it looks like to me is that connections are not being returned to the pool after I close the SqlSession. I have mysql set to timeout idle connections after 60 seconds and the connection pool to time out idle connections after 50 seconds. Again this was not an issue in 240.
>>>>>
>>>>> Any suggestions?
>>>>>
>>>>> Cheers
>>>>>
>>>>> François
>>>>>
>>>>>
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:8)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:61)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:53)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:38)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.sql.IBatis.selectObject(IBatis.java:554)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.dictionaries.Category.fromCategoryName(Category.java:118)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.ItemCategory.<init>(ItemCategory.java:201)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.ItemCategory.<init>(ItemCategory.java:227)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.Item.addItemCategory(Item.java:2182)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.processors.FeedProcessor.processEntryCategories(FeedProcessor.java:2494)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.processors.FeedProcessor.process(FeedProcessor.java:823)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.crawl(Worker.java:1313)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.crawlSourceKey(Worker.java:681)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.run(Worker.java:591)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.lang.Thread.run(Thread.java:619)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] WARN  com.poplar.crawler.Worker - Failed to crawl the source key: 'C01240E19154BE7BDA3703F726D5A68190D4A540', exception: 'org.apache.ibatis.exceptions.IbatisException:
>>>>> ### Error querying database.  Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
>>>>>
>>>>> The last packet successfully received from the server was 104,024 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.
>>>>> ### The error may involve dictionaries.Category.selectObjectByCategoryName-Inline
>>>>> ### The error occurred while setting parameters
>>>>> ### Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
>>>>>
>>>>> The last packet successfully received from the server was 104,024 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.'.
>>>>>
>>>>>
>>>>> ---------------------------------------------------------------------
>>>>> To unsubscribe, e-mail: [hidden email]
>>>>> For additional commands, e-mail: [hidden email]
>>>>>
>>>>>
>>>>
>>>> ---------------------------------------------------------------------
>>>> To unsubscribe, e-mail: [hidden email]
>>>> For additional commands, e-mail: [hidden email]
>>>>
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: [hidden email]
>>> For additional commands, e-mail: [hidden email]
>>>
>>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [hidden email]
>> For additional commands, e-mail: [hidden email]
>>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: interesting exception in 3.0

Clinton Begin
Let me know if this is still a problem, and create a JIRA ticket if it is.  I should have some time this weekend to look into it.

Clinton

On Wed, May 5, 2010 at 9:16 PM, Clinton Begin <[hidden email]> wrote:
Two things to do:

* Create a JIRA ticket for this.  We'll continue conversation and
investigation there.

* Mount the source and step through one example transaction.  See if
you can verify that close isn't being called, and possibly why.

* Finally, out of curiosity, disable caching globally, and see if the
problem remains.

I did find one refactoring that is in this area.  I'll attempt to
recreate and verify this too.

Clinton

2010/5/5 François Schiettecatte <[hidden email]>:
> Clinton
>
> A little more information on this, I reverted back to 240 and the problem I reported did not occurs after a 24 hour run. I then went to the current release and the problem reappeared, everything else is the same, so there is an issue.
>
> What it looks like is going on is that connections are not being put back into the connection pool after they are closed and so time out when they are subsequently used by iBatis.  MySQL is set to close connections after 60 seconds and the pool is set to close them after being idle for 50 seconds. Yet what I am seeing is that connections are being used quite some time after the last packets have been sent over the wire:
>
> ### Error querying database.  Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> The last packet successfully received from the server was 60,858 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.
> ### The error may involve dictionaries.Category.selectObjectByCategoryID-Inline
> ### The error occurred while setting parameters
> ### Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
>
> What it feels like is that iBatis is hanging onto the connection and reusing it at a later time.
>
> What do you need from me to track this down?
>
> Cheers
>
> François
>
>
>
> On May 1, 2010, at 4:28 PM, Clinton Begin wrote:
>
>> Then no, I don't believe there have been any changes related to
>> connections or transactions between those versions.  You can have a
>> look at the change log if you like:
>>
>> https://issues.apache.org/jira/secure/BrowseProject.jspa?id=10601&subset=-1
>>
>> Or the subversion history as well.
>>
>> Clinton
>>
>> 2010/5/1 François Schiettecatte <[hidden email]>:
>>> I am using JDBC, with C3P0 as my data source.
>>>
>>> Cheers
>>> François
>>>
>>> On May 1, 2010, at 4:14 PM, Clinton Begin wrote:
>>>
>>>> The only code changes related to that were with managed transactions.
>>>> Which transacion manager are you using?  (JDBC or MANAGED)?
>>>>
>>>> Cheers,
>>>> Clinton
>>>>
>>>> 2010/5/1 François Schiettecatte <[hidden email]>:
>>>>> Hi
>>>>>
>>>>> I grabbed the latest, greatest release of 3.0 from :
>>>>>
>>>>>        http://people.apache.org/builds/ibatis/ibatis-3-core/ibatis-core-3.0-bundle.zip
>>>>>
>>>>> and am now getting an exception from time to time, but I was not getting it with the previous 3.0 beta release (240). I was wondering if there had been any change in the code which deals with connections and pool between those two releases. What it looks like to me is that connections are not being returned to the pool after I close the SqlSession. I have mysql set to timeout idle connections after 60 seconds and the connection pool to time out idle connections after 50 seconds. Again this was not an issue in 240.
>>>>>
>>>>> Any suggestions?
>>>>>
>>>>> Cheers
>>>>>
>>>>> François
>>>>>
>>>>>
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:8)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:61)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:53)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:38)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.sql.IBatis.selectObject(IBatis.java:554)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.dictionaries.Category.fromCategoryName(Category.java:118)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.ItemCategory.<init>(ItemCategory.java:201)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.ItemCategory.<init>(ItemCategory.java:227)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.Item.addItemCategory(Item.java:2182)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.processors.FeedProcessor.processEntryCategories(FeedProcessor.java:2494)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.processors.FeedProcessor.process(FeedProcessor.java:823)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.crawl(Worker.java:1313)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.crawlSourceKey(Worker.java:681)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.run(Worker.java:591)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.lang.Thread.run(Thread.java:619)
>>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] WARN  com.poplar.crawler.Worker - Failed to crawl the source key: 'C01240E19154BE7BDA3703F726D5A68190D4A540', exception: 'org.apache.ibatis.exceptions.IbatisException:
>>>>> ### Error querying database.  Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
>>>>>
>>>>> The last packet successfully received from the server was 104,024 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.
>>>>> ### The error may involve dictionaries.Category.selectObjectByCategoryName-Inline
>>>>> ### The error occurred while setting parameters
>>>>> ### Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
>>>>>
>>>>> The last packet successfully received from the server was 104,024 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.'.
>>>>>
>>>>>
>>>>> ---------------------------------------------------------------------
>>>>> To unsubscribe, e-mail: [hidden email]
>>>>> For additional commands, e-mail: [hidden email]
>>>>>
>>>>>
>>>>
>>>> ---------------------------------------------------------------------
>>>> To unsubscribe, e-mail: [hidden email]
>>>> For additional commands, e-mail: [hidden email]
>>>>
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: [hidden email]
>>> For additional commands, e-mail: [hidden email]
>>>
>>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [hidden email]
>> For additional commands, e-mail: [hidden email]
>>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>

Reply | Threaded
Open this post in threaded view
|

Re: interesting exception in 3.0

François Schiettecatte
Clinton

Thanks for pinging me.

I have not had a chance to look at it, and it is still an issue, before rushing out and creating a jira ticket for it I wanted to look at the code diffs between the two releases, I will try to get to it later today or this WE.

François

On May 7, 2010, at 10:33 AM, Clinton Begin wrote:

> Let me know if this is still a problem, and create a JIRA ticket if it is.  I should have some time this weekend to look into it.
>
> Clinton
>
> On Wed, May 5, 2010 at 9:16 PM, Clinton Begin <[hidden email]> wrote:
> Two things to do:
>
> * Create a JIRA ticket for this.  We'll continue conversation and
> investigation there.
>
> * Mount the source and step through one example transaction.  See if
> you can verify that close isn't being called, and possibly why.
>
> * Finally, out of curiosity, disable caching globally, and see if the
> problem remains.
>
> I did find one refactoring that is in this area.  I'll attempt to
> recreate and verify this too.
>
> Clinton
>
> 2010/5/5 François Schiettecatte <[hidden email]>:
> > Clinton
> >
> > A little more information on this, I reverted back to 240 and the problem I reported did not occurs after a 24 hour run. I then went to the current release and the problem reappeared, everything else is the same, so there is an issue.
> >
> > What it looks like is going on is that connections are not being put back into the connection pool after they are closed and so time out when they are subsequently used by iBatis.  MySQL is set to close connections after 60 seconds and the pool is set to close them after being idle for 50 seconds. Yet what I am seeing is that connections are being used quite some time after the last packets have been sent over the wire:
> >
> > ### Error querying database.  Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> > The last packet successfully received from the server was 60,858 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.
> > ### The error may involve dictionaries.Category.selectObjectByCategoryID-Inline
> > ### The error occurred while setting parameters
> > ### Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> >
> > What it feels like is that iBatis is hanging onto the connection and reusing it at a later time.
> >
> > What do you need from me to track this down?
> >
> > Cheers
> >
> > François
> >
> >
> >
> > On May 1, 2010, at 4:28 PM, Clinton Begin wrote:
> >
> >> Then no, I don't believe there have been any changes related to
> >> connections or transactions between those versions.  You can have a
> >> look at the change log if you like:
> >>
> >> https://issues.apache.org/jira/secure/BrowseProject.jspa?id=10601&subset=-1
> >>
> >> Or the subversion history as well.
> >>
> >> Clinton
> >>
> >> 2010/5/1 François Schiettecatte <[hidden email]>:
> >>> I am using JDBC, with C3P0 as my data source.
> >>>
> >>> Cheers
> >>> François
> >>>
> >>> On May 1, 2010, at 4:14 PM, Clinton Begin wrote:
> >>>
> >>>> The only code changes related to that were with managed transactions.
> >>>> Which transacion manager are you using?  (JDBC or MANAGED)?
> >>>>
> >>>> Cheers,
> >>>> Clinton
> >>>>
> >>>> 2010/5/1 François Schiettecatte <[hidden email]>:
> >>>>> Hi
> >>>>>
> >>>>> I grabbed the latest, greatest release of 3.0 from :
> >>>>>
> >>>>>        http://people.apache.org/builds/ibatis/ibatis-3-core/ibatis-core-3.0-bundle.zip
> >>>>>
> >>>>> and am now getting an exception from time to time, but I was not getting it with the previous 3.0 beta release (240). I was wondering if there had been any change in the code which deals with connections and pool between those two releases. What it looks like to me is that connections are not being returned to the pool after I close the SqlSession. I have mysql set to timeout idle connections after 60 seconds and the connection pool to time out idle connections after 50 seconds. Again this was not an issue in 240.
> >>>>>
> >>>>> Any suggestions?
> >>>>>
> >>>>> Cheers
> >>>>>
> >>>>> François
> >>>>>
> >>>>>
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:8)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:61)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:53)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:38)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.sql.IBatis.selectObject(IBatis.java:554)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.dictionaries.Category.fromCategoryName(Category.java:118)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.ItemCategory.<init>(ItemCategory.java:201)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.ItemCategory.<init>(ItemCategory.java:227)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.Item.addItemCategory(Item.java:2182)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.processors.FeedProcessor.processEntryCategories(FeedProcessor.java:2494)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.processors.FeedProcessor.process(FeedProcessor.java:823)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.crawl(Worker.java:1313)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.crawlSourceKey(Worker.java:681)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.run(Worker.java:591)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.lang.Thread.run(Thread.java:619)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] WARN  com.poplar.crawler.Worker - Failed to crawl the source key: 'C01240E19154BE7BDA3703F726D5A68190D4A540', exception: 'org.apache.ibatis.exceptions.IbatisException:
> >>>>> ### Error querying database.  Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> >>>>>
> >>>>> The last packet successfully received from the server was 104,024 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.
> >>>>> ### The error may involve dictionaries.Category.selectObjectByCategoryName-Inline
> >>>>> ### The error occurred while setting parameters
> >>>>> ### Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> >>>>>
> >>>>> The last packet successfully received from the server was 104,024 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.'.
> >>>>>
> >>>>>
> >>>>> ---------------------------------------------------------------------
> >>>>> To unsubscribe, e-mail: [hidden email]
> >>>>> For additional commands, e-mail: [hidden email]
> >>>>>
> >>>>>
> >>>>
> >>>> ---------------------------------------------------------------------
> >>>> To unsubscribe, e-mail: [hidden email]
> >>>> For additional commands, e-mail: [hidden email]
> >>>>
> >>>
> >>>
> >>> ---------------------------------------------------------------------
> >>> To unsubscribe, e-mail: [hidden email]
> >>> For additional commands, e-mail: [hidden email]
> >>>
> >>>
> >>
> >> ---------------------------------------------------------------------
> >> To unsubscribe, e-mail: [hidden email]
> >> For additional commands, e-mail: [hidden email]
> >>
> >
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: [hidden email]
> > For additional commands, e-mail: [hidden email]
> >
> >
>


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: interesting exception in 3.0

Clinton Begin
Hi Francois,

I can't recreate this problem.  I've verified in about 1000 unit tests with different configurations that close is being called.  The only known and verified case of this was with the ManagedTransaction, not the JdbcTransaction.

Perhaps you can put together a simple unit test with HSQLDB or Derby (our two unit testing DBs) and zip it up and attach it to a ticket.  Please let me know, as I won't cut a release with a bug this serious, if it can be verified.

Cheers,
Clinton

2010/5/7 François Schiettecatte <[hidden email]>
Clinton

Thanks for pinging me.

I have not had a chance to look at it, and it is still an issue, before rushing out and creating a jira ticket for it I wanted to look at the code diffs between the two releases, I will try to get to it later today or this WE.

François

On May 7, 2010, at 10:33 AM, Clinton Begin wrote:

> Let me know if this is still a problem, and create a JIRA ticket if it is.  I should have some time this weekend to look into it.
>
> Clinton
>
> On Wed, May 5, 2010 at 9:16 PM, Clinton Begin <[hidden email]> wrote:
> Two things to do:
>
> * Create a JIRA ticket for this.  We'll continue conversation and
> investigation there.
>
> * Mount the source and step through one example transaction.  See if
> you can verify that close isn't being called, and possibly why.
>
> * Finally, out of curiosity, disable caching globally, and see if the
> problem remains.
>
> I did find one refactoring that is in this area.  I'll attempt to
> recreate and verify this too.
>
> Clinton
>
> 2010/5/5 François Schiettecatte <[hidden email]>:
> > Clinton
> >
> > A little more information on this, I reverted back to 240 and the problem I reported did not occurs after a 24 hour run. I then went to the current release and the problem reappeared, everything else is the same, so there is an issue.
> >
> > What it looks like is going on is that connections are not being put back into the connection pool after they are closed and so time out when they are subsequently used by iBatis.  MySQL is set to close connections after 60 seconds and the pool is set to close them after being idle for 50 seconds. Yet what I am seeing is that connections are being used quite some time after the last packets have been sent over the wire:
> >
> > ### Error querying database.  Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> > The last packet successfully received from the server was 60,858 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.
> > ### The error may involve dictionaries.Category.selectObjectByCategoryID-Inline
> > ### The error occurred while setting parameters
> > ### Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> >
> > What it feels like is that iBatis is hanging onto the connection and reusing it at a later time.
> >
> > What do you need from me to track this down?
> >
> > Cheers
> >
> > François
> >
> >
> >
> > On May 1, 2010, at 4:28 PM, Clinton Begin wrote:
> >
> >> Then no, I don't believe there have been any changes related to
> >> connections or transactions between those versions.  You can have a
> >> look at the change log if you like:
> >>
> >> https://issues.apache.org/jira/secure/BrowseProject.jspa?id=10601&subset=-1
> >>
> >> Or the subversion history as well.
> >>
> >> Clinton
> >>
> >> 2010/5/1 François Schiettecatte <[hidden email]>:
> >>> I am using JDBC, with C3P0 as my data source.
> >>>
> >>> Cheers
> >>> François
> >>>
> >>> On May 1, 2010, at 4:14 PM, Clinton Begin wrote:
> >>>
> >>>> The only code changes related to that were with managed transactions.
> >>>> Which transacion manager are you using?  (JDBC or MANAGED)?
> >>>>
> >>>> Cheers,
> >>>> Clinton
> >>>>
> >>>> 2010/5/1 François Schiettecatte <[hidden email]>:
> >>>>> Hi
> >>>>>
> >>>>> I grabbed the latest, greatest release of 3.0 from :
> >>>>>
> >>>>>        http://people.apache.org/builds/ibatis/ibatis-3-core/ibatis-core-3.0-bundle.zip
> >>>>>
> >>>>> and am now getting an exception from time to time, but I was not getting it with the previous 3.0 beta release (240). I was wondering if there had been any change in the code which deals with connections and pool between those two releases. What it looks like to me is that connections are not being returned to the pool after I close the SqlSession. I have mysql set to timeout idle connections after 60 seconds and the connection pool to time out idle connections after 50 seconds. Again this was not an issue in 240.
> >>>>>
> >>>>> Any suggestions?
> >>>>>
> >>>>> Cheers
> >>>>>
> >>>>> François
> >>>>>
> >>>>>
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:8)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:61)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:53)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:38)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.sql.IBatis.selectObject(IBatis.java:554)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.dictionaries.Category.fromCategoryName(Category.java:118)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.ItemCategory.<init>(ItemCategory.java:201)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.ItemCategory.<init>(ItemCategory.java:227)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.Item.addItemCategory(Item.java:2182)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.processors.FeedProcessor.processEntryCategories(FeedProcessor.java:2494)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.processors.FeedProcessor.process(FeedProcessor.java:823)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.crawl(Worker.java:1313)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.crawlSourceKey(Worker.java:681)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.run(Worker.java:591)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.lang.Thread.run(Thread.java:619)
> >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] WARN  com.poplar.crawler.Worker - Failed to crawl the source key: 'C01240E19154BE7BDA3703F726D5A68190D4A540', exception: 'org.apache.ibatis.exceptions.IbatisException:
> >>>>> ### Error querying database.  Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> >>>>>
> >>>>> The last packet successfully received from the server was 104,024 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.
> >>>>> ### The error may involve dictionaries.Category.selectObjectByCategoryName-Inline
> >>>>> ### The error occurred while setting parameters
> >>>>> ### Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> >>>>>
> >>>>> The last packet successfully received from the server was 104,024 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.'.
> >>>>>
> >>>>>
> >>>>> ---------------------------------------------------------------------
> >>>>> To unsubscribe, e-mail: [hidden email]
> >>>>> For additional commands, e-mail: [hidden email]
> >>>>>
> >>>>>
> >>>>
> >>>> ---------------------------------------------------------------------
> >>>> To unsubscribe, e-mail: [hidden email]
> >>>> For additional commands, e-mail: [hidden email]
> >>>>
> >>>
> >>>
> >>> ---------------------------------------------------------------------
> >>> To unsubscribe, e-mail: [hidden email]
> >>> For additional commands, e-mail: [hidden email]
> >>>
> >>>
> >>
> >> ---------------------------------------------------------------------
> >> To unsubscribe, e-mail: [hidden email]
> >> For additional commands, e-mail: [hidden email]
> >>
> >
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: [hidden email]
> > For additional commands, e-mail: [hidden email]
> >
> >
>


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]


Reply | Threaded
Open this post in threaded view
|

Re: interesting exception in 3.0

François Schiettecatte
Clinton

I understand, I am looking into it now, if I cant verify it before the weekend is over then I would say that something else is going on in my config.

François

On May 8, 2010, at 9:41 AM, Clinton Begin wrote:

> Hi Francois,
>
> I can't recreate this problem.  I've verified in about 1000 unit tests with different configurations that close is being called.  The only known and verified case of this was with the ManagedTransaction, not the JdbcTransaction.
>
> Perhaps you can put together a simple unit test with HSQLDB or Derby (our two unit testing DBs) and zip it up and attach it to a ticket.  Please let me know, as I won't cut a release with a bug this serious, if it can be verified.
>
> Cheers,
> Clinton
>
> 2010/5/7 François Schiettecatte <[hidden email]>
> Clinton
>
> Thanks for pinging me.
>
> I have not had a chance to look at it, and it is still an issue, before rushing out and creating a jira ticket for it I wanted to look at the code diffs between the two releases, I will try to get to it later today or this WE.
>
> François
>
> On May 7, 2010, at 10:33 AM, Clinton Begin wrote:
>
> > Let me know if this is still a problem, and create a JIRA ticket if it is.  I should have some time this weekend to look into it.
> >
> > Clinton
> >
> > On Wed, May 5, 2010 at 9:16 PM, Clinton Begin <[hidden email]> wrote:
> > Two things to do:
> >
> > * Create a JIRA ticket for this.  We'll continue conversation and
> > investigation there.
> >
> > * Mount the source and step through one example transaction.  See if
> > you can verify that close isn't being called, and possibly why.
> >
> > * Finally, out of curiosity, disable caching globally, and see if the
> > problem remains.
> >
> > I did find one refactoring that is in this area.  I'll attempt to
> > recreate and verify this too.
> >
> > Clinton
> >
> > 2010/5/5 François Schiettecatte <[hidden email]>:
> > > Clinton
> > >
> > > A little more information on this, I reverted back to 240 and the problem I reported did not occurs after a 24 hour run. I then went to the current release and the problem reappeared, everything else is the same, so there is an issue.
> > >
> > > What it looks like is going on is that connections are not being put back into the connection pool after they are closed and so time out when they are subsequently used by iBatis.  MySQL is set to close connections after 60 seconds and the pool is set to close them after being idle for 50 seconds. Yet what I am seeing is that connections are being used quite some time after the last packets have been sent over the wire:
> > >
> > > ### Error querying database.  Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> > > The last packet successfully received from the server was 60,858 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.
> > > ### The error may involve dictionaries.Category.selectObjectByCategoryID-Inline
> > > ### The error occurred while setting parameters
> > > ### Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> > >
> > > What it feels like is that iBatis is hanging onto the connection and reusing it at a later time.
> > >
> > > What do you need from me to track this down?
> > >
> > > Cheers
> > >
> > > François
> > >
> > >
> > >
> > > On May 1, 2010, at 4:28 PM, Clinton Begin wrote:
> > >
> > >> Then no, I don't believe there have been any changes related to
> > >> connections or transactions between those versions.  You can have a
> > >> look at the change log if you like:
> > >>
> > >> https://issues.apache.org/jira/secure/BrowseProject.jspa?id=10601&subset=-1
> > >>
> > >> Or the subversion history as well.
> > >>
> > >> Clinton
> > >>
> > >> 2010/5/1 François Schiettecatte <[hidden email]>:
> > >>> I am using JDBC, with C3P0 as my data source.
> > >>>
> > >>> Cheers
> > >>> François
> > >>>
> > >>> On May 1, 2010, at 4:14 PM, Clinton Begin wrote:
> > >>>
> > >>>> The only code changes related to that were with managed transactions.
> > >>>> Which transacion manager are you using?  (JDBC or MANAGED)?
> > >>>>
> > >>>> Cheers,
> > >>>> Clinton
> > >>>>
> > >>>> 2010/5/1 François Schiettecatte <[hidden email]>:
> > >>>>> Hi
> > >>>>>
> > >>>>> I grabbed the latest, greatest release of 3.0 from :
> > >>>>>
> > >>>>>        http://people.apache.org/builds/ibatis/ibatis-3-core/ibatis-core-3.0-bundle.zip
> > >>>>>
> > >>>>> and am now getting an exception from time to time, but I was not getting it with the previous 3.0 beta release (240). I was wondering if there had been any change in the code which deals with connections and pool between those two releases. What it looks like to me is that connections are not being returned to the pool after I close the SqlSession. I have mysql set to timeout idle connections after 60 seconds and the connection pool to time out idle connections after 50 seconds. Again this was not an issue in 240.
> > >>>>>
> > >>>>> Any suggestions?
> > >>>>>
> > >>>>> Cheers
> > >>>>>
> > >>>>> François
> > >>>>>
> > >>>>>
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:8)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:61)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:53)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:38)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.sql.IBatis.selectObject(IBatis.java:554)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.dictionaries.Category.fromCategoryName(Category.java:118)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.ItemCategory.<init>(ItemCategory.java:201)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.ItemCategory.<init>(ItemCategory.java:227)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.Item.addItemCategory(Item.java:2182)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.processors.FeedProcessor.processEntryCategories(FeedProcessor.java:2494)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.processors.FeedProcessor.process(FeedProcessor.java:823)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.crawl(Worker.java:1313)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.crawlSourceKey(Worker.java:681)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.run(Worker.java:591)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.lang.Thread.run(Thread.java:619)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] WARN  com.poplar.crawler.Worker - Failed to crawl the source key: 'C01240E19154BE7BDA3703F726D5A68190D4A540', exception: 'org.apache.ibatis.exceptions.IbatisException:
> > >>>>> ### Error querying database.  Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> > >>>>>
> > >>>>> The last packet successfully received from the server was 104,024 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.
> > >>>>> ### The error may involve dictionaries.Category.selectObjectByCategoryName-Inline
> > >>>>> ### The error occurred while setting parameters
> > >>>>> ### Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> > >>>>>
> > >>>>> The last packet successfully received from the server was 104,024 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.'.
> > >>>>>
> > >>>>>
> > >>>>> ---------------------------------------------------------------------
> > >>>>> To unsubscribe, e-mail: [hidden email]
> > >>>>> For additional commands, e-mail: [hidden email]
> > >>>>>
> > >>>>>
> > >>>>
> > >>>> ---------------------------------------------------------------------
> > >>>> To unsubscribe, e-mail: [hidden email]
> > >>>> For additional commands, e-mail: [hidden email]
> > >>>>
> > >>>
> > >>>
> > >>> ---------------------------------------------------------------------
> > >>> To unsubscribe, e-mail: [hidden email]
> > >>> For additional commands, e-mail: [hidden email]
> > >>>
> > >>>
> > >>
> > >> ---------------------------------------------------------------------
> > >> To unsubscribe, e-mail: [hidden email]
> > >> For additional commands, e-mail: [hidden email]
> > >>
> > >
> > >
> > > ---------------------------------------------------------------------
> > > To unsubscribe, e-mail: [hidden email]
> > > For additional commands, e-mail: [hidden email]
> > >
> > >
> >
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: interesting exception in 3.0

François Schiettecatte
In reply to this post by Clinton Begin
Clinton

I am getting closer, I was able to make the issue go away by selectively rolling back some of the changes that were made between the two version around the handling of transaction and rollbacks. The problem is that I dont have sure-fire test case for this, I have to run a crawler for 3-4 hours before the problem manifests itself. Hopefully I will have the code narrowed down enough to identify the issue.

Since I am the only one with this issue, don't wait for me to cut a release. What I will do is check for the issue in the new release and carry on working on this if the issue is still there.

Cheers

François

On May 8, 2010, at 9:41 AM, Clinton Begin wrote:

> Hi Francois,
>
> I can't recreate this problem.  I've verified in about 1000 unit tests with different configurations that close is being called.  The only known and verified case of this was with the ManagedTransaction, not the JdbcTransaction.
>
> Perhaps you can put together a simple unit test with HSQLDB or Derby (our two unit testing DBs) and zip it up and attach it to a ticket.  Please let me know, as I won't cut a release with a bug this serious, if it can be verified.
>
> Cheers,
> Clinton
>
> 2010/5/7 François Schiettecatte <[hidden email]>
> Clinton
>
> Thanks for pinging me.
>
> I have not had a chance to look at it, and it is still an issue, before rushing out and creating a jira ticket for it I wanted to look at the code diffs between the two releases, I will try to get to it later today or this WE.
>
> François
>
> On May 7, 2010, at 10:33 AM, Clinton Begin wrote:
>
> > Let me know if this is still a problem, and create a JIRA ticket if it is.  I should have some time this weekend to look into it.
> >
> > Clinton
> >
> > On Wed, May 5, 2010 at 9:16 PM, Clinton Begin <[hidden email]> wrote:
> > Two things to do:
> >
> > * Create a JIRA ticket for this.  We'll continue conversation and
> > investigation there.
> >
> > * Mount the source and step through one example transaction.  See if
> > you can verify that close isn't being called, and possibly why.
> >
> > * Finally, out of curiosity, disable caching globally, and see if the
> > problem remains.
> >
> > I did find one refactoring that is in this area.  I'll attempt to
> > recreate and verify this too.
> >
> > Clinton
> >
> > 2010/5/5 François Schiettecatte <[hidden email]>:
> > > Clinton
> > >
> > > A little more information on this, I reverted back to 240 and the problem I reported did not occurs after a 24 hour run. I then went to the current release and the problem reappeared, everything else is the same, so there is an issue.
> > >
> > > What it looks like is going on is that connections are not being put back into the connection pool after they are closed and so time out when they are subsequently used by iBatis.  MySQL is set to close connections after 60 seconds and the pool is set to close them after being idle for 50 seconds. Yet what I am seeing is that connections are being used quite some time after the last packets have been sent over the wire:
> > >
> > > ### Error querying database.  Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> > > The last packet successfully received from the server was 60,858 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.
> > > ### The error may involve dictionaries.Category.selectObjectByCategoryID-Inline
> > > ### The error occurred while setting parameters
> > > ### Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> > >
> > > What it feels like is that iBatis is hanging onto the connection and reusing it at a later time.
> > >
> > > What do you need from me to track this down?
> > >
> > > Cheers
> > >
> > > François
> > >
> > >
> > >
> > > On May 1, 2010, at 4:28 PM, Clinton Begin wrote:
> > >
> > >> Then no, I don't believe there have been any changes related to
> > >> connections or transactions between those versions.  You can have a
> > >> look at the change log if you like:
> > >>
> > >> https://issues.apache.org/jira/secure/BrowseProject.jspa?id=10601&subset=-1
> > >>
> > >> Or the subversion history as well.
> > >>
> > >> Clinton
> > >>
> > >> 2010/5/1 François Schiettecatte <[hidden email]>:
> > >>> I am using JDBC, with C3P0 as my data source.
> > >>>
> > >>> Cheers
> > >>> François
> > >>>
> > >>> On May 1, 2010, at 4:14 PM, Clinton Begin wrote:
> > >>>
> > >>>> The only code changes related to that were with managed transactions.
> > >>>> Which transacion manager are you using?  (JDBC or MANAGED)?
> > >>>>
> > >>>> Cheers,
> > >>>> Clinton
> > >>>>
> > >>>> 2010/5/1 François Schiettecatte <[hidden email]>:
> > >>>>> Hi
> > >>>>>
> > >>>>> I grabbed the latest, greatest release of 3.0 from :
> > >>>>>
> > >>>>>        http://people.apache.org/builds/ibatis/ibatis-3-core/ibatis-core-3.0-bundle.zip
> > >>>>>
> > >>>>> and am now getting an exception from time to time, but I was not getting it with the previous 3.0 beta release (240). I was wondering if there had been any change in the code which deals with connections and pool between those two releases. What it looks like to me is that connections are not being returned to the pool after I close the SqlSession. I have mysql set to timeout idle connections after 60 seconds and the connection pool to time out idle connections after 50 seconds. Again this was not an issue in 240.
> > >>>>>
> > >>>>> Any suggestions?
> > >>>>>
> > >>>>> Cheers
> > >>>>>
> > >>>>> François
> > >>>>>
> > >>>>>
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:8)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:61)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:53)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:38)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.sql.IBatis.selectObject(IBatis.java:554)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.dictionaries.Category.fromCategoryName(Category.java:118)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.ItemCategory.<init>(ItemCategory.java:201)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.ItemCategory.<init>(ItemCategory.java:227)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.Item.addItemCategory(Item.java:2182)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.processors.FeedProcessor.processEntryCategories(FeedProcessor.java:2494)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.processors.FeedProcessor.process(FeedProcessor.java:823)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.crawl(Worker.java:1313)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.crawlSourceKey(Worker.java:681)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.run(Worker.java:591)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.lang.Thread.run(Thread.java:619)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] WARN  com.poplar.crawler.Worker - Failed to crawl the source key: 'C01240E19154BE7BDA3703F726D5A68190D4A540', exception: 'org.apache.ibatis.exceptions.IbatisException:
> > >>>>> ### Error querying database.  Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> > >>>>>
> > >>>>> The last packet successfully received from the server was 104,024 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.
> > >>>>> ### The error may involve dictionaries.Category.selectObjectByCategoryName-Inline
> > >>>>> ### The error occurred while setting parameters
> > >>>>> ### Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> > >>>>>
> > >>>>> The last packet successfully received from the server was 104,024 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.'.
> > >>>>>
> > >>>>>
> > >>>>> ---------------------------------------------------------------------
> > >>>>> To unsubscribe, e-mail: [hidden email]
> > >>>>> For additional commands, e-mail: [hidden email]
> > >>>>>
> > >>>>>
> > >>>>
> > >>>> ---------------------------------------------------------------------
> > >>>> To unsubscribe, e-mail: [hidden email]
> > >>>> For additional commands, e-mail: [hidden email]
> > >>>>
> > >>>
> > >>>
> > >>> ---------------------------------------------------------------------
> > >>> To unsubscribe, e-mail: [hidden email]
> > >>> For additional commands, e-mail: [hidden email]
> > >>>
> > >>>
> > >>
> > >> ---------------------------------------------------------------------
> > >> To unsubscribe, e-mail: [hidden email]
> > >> For additional commands, e-mail: [hidden email]
> > >>
> > >
> > >
> > > ---------------------------------------------------------------------
> > > To unsubscribe, e-mail: [hidden email]
> > > For additional commands, e-mail: [hidden email]
> > >
> > >
> >
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: interesting exception in 3.0

François Schiettecatte
In reply to this post by Clinton Begin
Clinton

Ok this is interesting, I was able to reliably replicate the problem, I even grabbed the source code and included in the source code tree of my application and still got the issue, but... the server I am running this one was rebooted due to a power failure and now the problem has gone away... I blame cosmic rays at this point...

So this is not an issue.

Cheers

François


On May 8, 2010, at 9:41 AM, Clinton Begin wrote:

> Hi Francois,
>
> I can't recreate this problem.  I've verified in about 1000 unit tests with different configurations that close is being called.  The only known and verified case of this was with the ManagedTransaction, not the JdbcTransaction.
>
> Perhaps you can put together a simple unit test with HSQLDB or Derby (our two unit testing DBs) and zip it up and attach it to a ticket.  Please let me know, as I won't cut a release with a bug this serious, if it can be verified.
>
> Cheers,
> Clinton
>
> 2010/5/7 François Schiettecatte <[hidden email]>
> Clinton
>
> Thanks for pinging me.
>
> I have not had a chance to look at it, and it is still an issue, before rushing out and creating a jira ticket for it I wanted to look at the code diffs between the two releases, I will try to get to it later today or this WE.
>
> François
>
> On May 7, 2010, at 10:33 AM, Clinton Begin wrote:
>
> > Let me know if this is still a problem, and create a JIRA ticket if it is.  I should have some time this weekend to look into it.
> >
> > Clinton
> >
> > On Wed, May 5, 2010 at 9:16 PM, Clinton Begin <[hidden email]> wrote:
> > Two things to do:
> >
> > * Create a JIRA ticket for this.  We'll continue conversation and
> > investigation there.
> >
> > * Mount the source and step through one example transaction.  See if
> > you can verify that close isn't being called, and possibly why.
> >
> > * Finally, out of curiosity, disable caching globally, and see if the
> > problem remains.
> >
> > I did find one refactoring that is in this area.  I'll attempt to
> > recreate and verify this too.
> >
> > Clinton
> >
> > 2010/5/5 François Schiettecatte <[hidden email]>:
> > > Clinton
> > >
> > > A little more information on this, I reverted back to 240 and the problem I reported did not occurs after a 24 hour run. I then went to the current release and the problem reappeared, everything else is the same, so there is an issue.
> > >
> > > What it looks like is going on is that connections are not being put back into the connection pool after they are closed and so time out when they are subsequently used by iBatis.  MySQL is set to close connections after 60 seconds and the pool is set to close them after being idle for 50 seconds. Yet what I am seeing is that connections are being used quite some time after the last packets have been sent over the wire:
> > >
> > > ### Error querying database.  Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> > > The last packet successfully received from the server was 60,858 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.
> > > ### The error may involve dictionaries.Category.selectObjectByCategoryID-Inline
> > > ### The error occurred while setting parameters
> > > ### Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> > >
> > > What it feels like is that iBatis is hanging onto the connection and reusing it at a later time.
> > >
> > > What do you need from me to track this down?
> > >
> > > Cheers
> > >
> > > François
> > >
> > >
> > >
> > > On May 1, 2010, at 4:28 PM, Clinton Begin wrote:
> > >
> > >> Then no, I don't believe there have been any changes related to
> > >> connections or transactions between those versions.  You can have a
> > >> look at the change log if you like:
> > >>
> > >> https://issues.apache.org/jira/secure/BrowseProject.jspa?id=10601&subset=-1
> > >>
> > >> Or the subversion history as well.
> > >>
> > >> Clinton
> > >>
> > >> 2010/5/1 François Schiettecatte <[hidden email]>:
> > >>> I am using JDBC, with C3P0 as my data source.
> > >>>
> > >>> Cheers
> > >>> François
> > >>>
> > >>> On May 1, 2010, at 4:14 PM, Clinton Begin wrote:
> > >>>
> > >>>> The only code changes related to that were with managed transactions.
> > >>>> Which transacion manager are you using?  (JDBC or MANAGED)?
> > >>>>
> > >>>> Cheers,
> > >>>> Clinton
> > >>>>
> > >>>> 2010/5/1 François Schiettecatte <[hidden email]>:
> > >>>>> Hi
> > >>>>>
> > >>>>> I grabbed the latest, greatest release of 3.0 from :
> > >>>>>
> > >>>>>        http://people.apache.org/builds/ibatis/ibatis-3-core/ibatis-core-3.0-bundle.zip
> > >>>>>
> > >>>>> and am now getting an exception from time to time, but I was not getting it with the previous 3.0 beta release (240). I was wondering if there had been any change in the code which deals with connections and pool between those two releases. What it looks like to me is that connections are not being returned to the pool after I close the SqlSession. I have mysql set to timeout idle connections after 60 seconds and the connection pool to time out idle connections after 50 seconds. Again this was not an issue in 240.
> > >>>>>
> > >>>>> Any suggestions?
> > >>>>>
> > >>>>> Cheers
> > >>>>>
> > >>>>> François
> > >>>>>
> > >>>>>
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:8)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:61)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:53)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:38)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.sql.IBatis.selectObject(IBatis.java:554)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.dictionaries.Category.fromCategoryName(Category.java:118)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.ItemCategory.<init>(ItemCategory.java:201)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.ItemCategory.<init>(ItemCategory.java:227)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.Item.addItemCategory(Item.java:2182)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.processors.FeedProcessor.processEntryCategories(FeedProcessor.java:2494)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.processors.FeedProcessor.process(FeedProcessor.java:823)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.crawl(Worker.java:1313)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.crawlSourceKey(Worker.java:681)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.run(Worker.java:591)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.lang.Thread.run(Thread.java:619)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] WARN  com.poplar.crawler.Worker - Failed to crawl the source key: 'C01240E19154BE7BDA3703F726D5A68190D4A540', exception: 'org.apache.ibatis.exceptions.IbatisException:
> > >>>>> ### Error querying database.  Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> > >>>>>
> > >>>>> The last packet successfully received from the server was 104,024 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.
> > >>>>> ### The error may involve dictionaries.Category.selectObjectByCategoryName-Inline
> > >>>>> ### The error occurred while setting parameters
> > >>>>> ### Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> > >>>>>
> > >>>>> The last packet successfully received from the server was 104,024 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.'.
> > >>>>>
> > >>>>>
> > >>>>> ---------------------------------------------------------------------
> > >>>>> To unsubscribe, e-mail: [hidden email]
> > >>>>> For additional commands, e-mail: [hidden email]
> > >>>>>
> > >>>>>
> > >>>>
> > >>>> ---------------------------------------------------------------------
> > >>>> To unsubscribe, e-mail: [hidden email]
> > >>>> For additional commands, e-mail: [hidden email]
> > >>>>
> > >>>
> > >>>
> > >>> ---------------------------------------------------------------------
> > >>> To unsubscribe, e-mail: [hidden email]
> > >>> For additional commands, e-mail: [hidden email]
> > >>>
> > >>>
> > >>
> > >> ---------------------------------------------------------------------
> > >> To unsubscribe, e-mail: [hidden email]
> > >> For additional commands, e-mail: [hidden email]
> > >>
> > >
> > >
> > > ---------------------------------------------------------------------
> > > To unsubscribe, e-mail: [hidden email]
> > > For additional commands, e-mail: [hidden email]
> > >
> > >
> >
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: interesting exception in 3.0

Clinton Begin
Thanks so much Francois, I appreciate the effort you applied to validating this.

Cheers,
Clinton

2010/5/14 François Schiettecatte <[hidden email]>
Clinton

Ok this is interesting, I was able to reliably replicate the problem, I even grabbed the source code and included in the source code tree of my application and still got the issue, but... the server I am running this one was rebooted due to a power failure and now the problem has gone away... I blame cosmic rays at this point...

So this is not an issue.

Cheers

François


On May 8, 2010, at 9:41 AM, Clinton Begin wrote:

> Hi Francois,
>
> I can't recreate this problem.  I've verified in about 1000 unit tests with different configurations that close is being called.  The only known and verified case of this was with the ManagedTransaction, not the JdbcTransaction.
>
> Perhaps you can put together a simple unit test with HSQLDB or Derby (our two unit testing DBs) and zip it up and attach it to a ticket.  Please let me know, as I won't cut a release with a bug this serious, if it can be verified.
>
> Cheers,
> Clinton
>
> 2010/5/7 François Schiettecatte <[hidden email]>
> Clinton
>
> Thanks for pinging me.
>
> I have not had a chance to look at it, and it is still an issue, before rushing out and creating a jira ticket for it I wanted to look at the code diffs between the two releases, I will try to get to it later today or this WE.
>
> François
>
> On May 7, 2010, at 10:33 AM, Clinton Begin wrote:
>
> > Let me know if this is still a problem, and create a JIRA ticket if it is.  I should have some time this weekend to look into it.
> >
> > Clinton
> >
> > On Wed, May 5, 2010 at 9:16 PM, Clinton Begin <[hidden email]> wrote:
> > Two things to do:
> >
> > * Create a JIRA ticket for this.  We'll continue conversation and
> > investigation there.
> >
> > * Mount the source and step through one example transaction.  See if
> > you can verify that close isn't being called, and possibly why.
> >
> > * Finally, out of curiosity, disable caching globally, and see if the
> > problem remains.
> >
> > I did find one refactoring that is in this area.  I'll attempt to
> > recreate and verify this too.
> >
> > Clinton
> >
> > 2010/5/5 François Schiettecatte <[hidden email]>:
> > > Clinton
> > >
> > > A little more information on this, I reverted back to 240 and the problem I reported did not occurs after a 24 hour run. I then went to the current release and the problem reappeared, everything else is the same, so there is an issue.
> > >
> > > What it looks like is going on is that connections are not being put back into the connection pool after they are closed and so time out when they are subsequently used by iBatis.  MySQL is set to close connections after 60 seconds and the pool is set to close them after being idle for 50 seconds. Yet what I am seeing is that connections are being used quite some time after the last packets have been sent over the wire:
> > >
> > > ### Error querying database.  Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> > > The last packet successfully received from the server was 60,858 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.
> > > ### The error may involve dictionaries.Category.selectObjectByCategoryID-Inline
> > > ### The error occurred while setting parameters
> > > ### Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> > >
> > > What it feels like is that iBatis is hanging onto the connection and reusing it at a later time.
> > >
> > > What do you need from me to track this down?
> > >
> > > Cheers
> > >
> > > François
> > >
> > >
> > >
> > > On May 1, 2010, at 4:28 PM, Clinton Begin wrote:
> > >
> > >> Then no, I don't believe there have been any changes related to
> > >> connections or transactions between those versions.  You can have a
> > >> look at the change log if you like:
> > >>
> > >> https://issues.apache.org/jira/secure/BrowseProject.jspa?id=10601&subset=-1
> > >>
> > >> Or the subversion history as well.
> > >>
> > >> Clinton
> > >>
> > >> 2010/5/1 François Schiettecatte <[hidden email]>:
> > >>> I am using JDBC, with C3P0 as my data source.
> > >>>
> > >>> Cheers
> > >>> François
> > >>>
> > >>> On May 1, 2010, at 4:14 PM, Clinton Begin wrote:
> > >>>
> > >>>> The only code changes related to that were with managed transactions.
> > >>>> Which transacion manager are you using?  (JDBC or MANAGED)?
> > >>>>
> > >>>> Cheers,
> > >>>> Clinton
> > >>>>
> > >>>> 2010/5/1 François Schiettecatte <[hidden email]>:
> > >>>>> Hi
> > >>>>>
> > >>>>> I grabbed the latest, greatest release of 3.0 from :
> > >>>>>
> > >>>>>        http://people.apache.org/builds/ibatis/ibatis-3-core/ibatis-core-3.0-bundle.zip
> > >>>>>
> > >>>>> and am now getting an exception from time to time, but I was not getting it with the previous 3.0 beta release (240). I was wondering if there had been any change in the code which deals with connections and pool between those two releases. What it looks like to me is that connections are not being returned to the pool after I close the SqlSession. I have mysql set to timeout idle connections after 60 seconds and the connection pool to time out idle connections after 50 seconds. Again this was not an issue in 240.
> > >>>>>
> > >>>>> Any suggestions?
> > >>>>>
> > >>>>> Cheers
> > >>>>>
> > >>>>> François
> > >>>>>
> > >>>>>
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:8)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:61)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:53)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:38)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.sql.IBatis.selectObject(IBatis.java:554)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.dictionaries.Category.fromCategoryName(Category.java:118)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.ItemCategory.<init>(ItemCategory.java:201)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.ItemCategory.<init>(ItemCategory.java:227)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.db.items.Item.addItemCategory(Item.java:2182)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.processors.FeedProcessor.processEntryCategories(FeedProcessor.java:2494)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.processors.FeedProcessor.process(FeedProcessor.java:823)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.crawl(Worker.java:1313)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.crawlSourceKey(Worker.java:681)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - com.poplar.crawler.Worker.run(Worker.java:591)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] ERROR com.poplar.crawler.Worker - java.lang.Thread.run(Thread.java:619)
> > >>>>> 2010-05-01 01:54:20,609 [pool-1-thread-1] WARN  com.poplar.crawler.Worker - Failed to crawl the source key: 'C01240E19154BE7BDA3703F726D5A68190D4A540', exception: 'org.apache.ibatis.exceptions.IbatisException:
> > >>>>> ### Error querying database.  Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> > >>>>>
> > >>>>> The last packet successfully received from the server was 104,024 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.
> > >>>>> ### The error may involve dictionaries.Category.selectObjectByCategoryName-Inline
> > >>>>> ### The error occurred while setting parameters
> > >>>>> ### Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> > >>>>>
> > >>>>> The last packet successfully received from the server was 104,024 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.'.
> > >>>>>
> > >>>>>
> > >>>>> ---------------------------------------------------------------------
> > >>>>> To unsubscribe, e-mail: [hidden email]
> > >>>>> For additional commands, e-mail: [hidden email]
> > >>>>>
> > >>>>>
> > >>>>
> > >>>> ---------------------------------------------------------------------
> > >>>> To unsubscribe, e-mail: [hidden email]
> > >>>> For additional commands, e-mail: [hidden email]
> > >>>>
> > >>>
> > >>>
> > >>> ---------------------------------------------------------------------
> > >>> To unsubscribe, e-mail: [hidden email]
> > >>> For additional commands, e-mail: [hidden email]
> > >>>
> > >>>
> > >>
> > >> ---------------------------------------------------------------------
> > >> To unsubscribe, e-mail: [hidden email]
> > >> For additional commands, e-mail: [hidden email]
> > >>
> > >
> > >
> > > ---------------------------------------------------------------------
> > > To unsubscribe, e-mail: [hidden email]
> > > For additional commands, e-mail: [hidden email]
> > >
> > >
> >
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]