Re: [iROD-Chat:9047] Java ClosedChannelException in Jargon 3.2.1

[mco...@unc.edu]

It is intermittent?

I dont see this in any test, but i will take a look.  Is it only for that one operation?  Did the irods agent die or segfault?

MC

From my Android phone on T-Mobile. The first nationwide 4G network.

----- Reply message -----
From: "Steve Handy" <steve...@gmail.com>
To: <irod...@googlegroups.com>
Subject: [iROD-Chat:9047] Java ClosedChannelException in Jargon 3.2.1
Date: Fri, Nov 16, 2012 11:45 am


Mike, I tried out the 3.2.1 version and am now consistently receiving this
exception with nearly every attempt to instantiate a DataObject using
DataObjectAO.findByAbsolutePath():

1485 [pool-4-thread-1] ERROR
org.irods.jargon.core.connection.IRODSCommands  irodsFunction 347-
ioexception
java.nio.channels.ClosedChannelException
       at
org.irods.jargon.core.connection.IRODSConnection.flush(IRODSConnection.java:742)
       at
org.irods.jargon.core.connection.IRODSCommands.irodsFunction(IRODSCommands.java:332)
       at
org.irods.jargon.core.connection.IRODSCommands.irodsFunction(IRODSCommands.java:270)
       at
org.irods.jargon.core.query.GenQueryProcessor.sendGenQueryAndReturnResponse(GenQueryProcessor.java:140)
       at
org.irods.jargon.core.query.GenQueryProcessor.executeTranslatedIRODSQuery(GenQueryProcessor.java:84)
       at
org.irods.jargon.core.pub.IRODSGenQueryExecutorImpl.executeIRODSQueryAndCloseResultInZone(IRODSGenQueryExecutorImpl.java:159)
       at
org.irods.jargon.core.pub.DataObjectAOImpl.findGivenObjStat(DataObjectAOImpl.java:252)
       at
org.irods.jargon.core.pub.DataObjectAOImpl.findByCollectionNameAndDataName(DataObjectAOImpl.java:150)
       at
org.irods.jargon.core.pub.DataObjectAOImpl.findByAbsolutePath(DataObjectAOImpl.java:174)

There is nothing additional to indicate an issue in the iRODS log.

--
"iRODS: the Integrated Rule-Oriented Data-management System; A community driven, open source, data grid software solution"   https://www.irods.org

iROD-Chat:  http://groups.google.com/group/iROD-Chat

[Steve Handy]

Mike, the behavior appears to be consistent.  I am running against an iRODS Server 3.2.  I thought that perhaps is was a change in the behavior of the IRODSFileSystem.closeAndEatExceptions() method I was using to close connections after each getOperation in my multithreaded application.  However, commenting out that line only resulted in a delay of the ClosedChannelExceptions, which were then followed by IOExceptions and SocketExceptions:

73263 [pool-4-thread-2] WARN  org.irods.jargon.core.connection.IRODSSimpleProtocolManager  returnConnectionWithIoException 88- connection returned with IOException, will forcefully close and remove from session cache
73263 [pool-4-thread-2] WARN  org.irods.jargon.core.connection.IRODSSession  discardSessionForErrors 460- discarding irods session for: irods://********@********:1247
73263 [pool-4-thread-2] ERROR org.irods.jargon.core.connection.IRODSConnection  read 863- io exception reading
java.io.IOException: Stream closed.
        at java.net.AbstractPlainSocketImpl.available(AbstractPlainSocketImpl.java:435)
        at java.net.SocketInputStream.available(SocketInputStream.java:234)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:342)
        at org.irods.jargon.core.connection.IRODSConnection.read(IRODSConnection.java:926)
        at org.irods.jargon.core.connection.IRODSConnection.read(IRODSConnection.java:841)
        at org.irods.jargon.core.connection.IRODSCommands.read(IRODSCommands.java:670)
        at org.irods.jargon.core.pub.DataAOHelper.processNormalGetTransfer(DataAOHelper.java:390)
        at org.irods.jargon.core.pub.DataObjectAOImpl.processGetAfterResourceDetermined(DataObjectAOImpl.java:1317)
        at org.irods.jargon.core.pub.DataObjectAOImpl.getDataObjectFromIrods(DataObjectAOImpl.java:1052)
        at org.irods.jargon.core.pub.TransferOperationsHelper.processGetOfSingleFile(TransferOperationsHelper.java:255)
        at org.irods.jargon.core.pub.DataTransferOperationsImpl.processGetOfSingleFile(DataTransferOperationsImpl.java:756)
        at org.irods.jargon.core.pub.DataTransferOperationsImpl.processGetAfterAnyConnectionRerouting(DataTransferOperationsImpl.java:544)
        at org.irods.jargon.core.pub.DataTransferOperationsImpl.getOperation(DataTransferOperationsImpl.java:369)
        at edu.stsci.irods.util2.StsciDataObject.copyFromIRODS(StsciDataObject.java:193)
        at edu.stsci.irods.util2.StsciIrodsUtilities.readIRODSFile(StsciIrodsUtilities.java:182)
        at edu.stsci.irods.performance.ReadTestConfiguration.runAsJargon(ReadTestConfiguration.java:88)
        at edu.stsci.irods.performance.AbstractTestConfiguration$2.run(AbstractTestConfiguration.java:131)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
        at java.lang.Thread.run(Thread.java:679)

and.....

77486 [pool-4-thread-4] ERROR org.irods.jargon.core.connection.IRODSCommands  irodsFunction 347- ioexception
java.net.SocketException: Socket closed
        at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:116)
        at java.net.SocketOutputStream.write(SocketOutputStream.java:153)
        at org.irods.jargon.core.connection.IRODSConnection.send(IRODSConnection.java:540)
        at org.irods.jargon.core.connection.IRODSCommands.irodsFunction(IRODSCommands.java:328)

        at org.irods.jargon.core.connection.IRODSCommands.irodsFunction(IRODSCommands.java:270)
        at org.irods.jargon.core.query.GenQueryProcessor.sendGenQueryAndReturnResponse(GenQueryProcessor.java:140)
        at org.irods.jargon.core.query.GenQueryProcessor.executeTranslatedIRODSQuery(GenQueryProcessor.java:84)
        at org.irods.jargon.core.pub.IRODSGenQueryExecutorImpl.executeIRODSQueryAndCloseResultInZone(IRODSGenQueryExecutorImpl.java:159)
        at org.irods.jargon.core.pub.DataObjectAOImpl.findGivenObjStat(DataObjectAOImpl.java:252)
        at org.irods.jargon.core.pub.DataObjectAOImpl.findByCollectionNameAndDataName(DataObjectAOImpl.java:150)
        at org.irods.jargon.core.pub.DataObjectAOImpl.findByAbsolutePath(DataObjectAOImpl.java:174)

        at edu.stsci.irods.util2.StsciDataObject.<init>(StsciDataObject.java:33)
        at edu.stsci.irods.util2.StsciIrodsUtilities.readIRODSFile(StsciIrodsUtilities.java:174)
        at edu.stsci.irods.performance.ReadTestConfiguration.runAsJargon(ReadTestConfiguration.java:88)
        at edu.stsci.irods.performance.AbstractTestConfiguration$2.run(AbstractTestConfiguration.java:131)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
        at java.lang.Thread.run(Thread.java:679)

Without that line commented out, I only get the ClosedChannelExceptions.  With it commented out, there is some information in the log.  There are a lot of intermittent blocks such as this:

Nov 16 15:41:01 pid:69264 ERROR: readMsgHeader:header read- read 0 bytes, expect 4, status = -4002
Nov 16 15:41:01 pid:69264 NOTICE: Agent exiting with status = -4002
Nov 16 15:41:01 pid:69260 ERROR: readMsgHeader:header read- read 0 bytes, expect 4, status = -4002
Nov 16 15:41:01 pid:69260 NOTICE: Agent exiting with status = -4002
Nov 16 15:41:01 pid:12877 NOTICE: Agent process 69260 exited with status 256
Nov 16 15:41:01 pid:12877 NOTICE: Agent process 69264 exited with status 256

Followed by a ton of blocks like this one:

Nov 16 15:41:05 pid:69608 NOTICE: chlOpen cmlOpen failure -803000
Nov 16 15:41:05 pid:69608 NOTICE: connectRcat: chlOpen Error. Status = -803000
Nov 16 15:41:05 pid:69608 SYSTEM FATAL: initServerInfo: no rcatHost error, status = -803000
Nov 16 15:41:05 pid:69608 ERROR: initAgent: initServerInfo error, status = -803000
Nov 16 15:41:05 pid:69608 NOTICE: Agent exiting with status = -803000
Nov 16 15:41:05 pid:12877 NOTICE: Agent process 69609 started for puser=******** and cuser=******** from 130.167.252.40
Nov 16 15:41:05 pid:12877 NOTICE: Agent process 69608 exited with status 256
Nov 16 15:41:05 pid:12877 NOTICE: Agent process 69611 started for puser=******** and cuser=******** from 130.167.252.40
Nov 16 15:41:05 pid:69609 ERROR: cllConnect: SQLConnect failed: -1
Nov 16 15:41:05 pid:69609 ERROR: cllConnect: SQLConnect failed:odbcEntry=PostgreSQL,user=*******,pass=********
Nov 16 15:41:05 pid:69609 ERROR: cllConnect:          SQLSTATE: 28000
Nov 16 15:41:05 pid:69609 ERROR: cllConnect:  Native Error Code: 210
Nov 16 15:41:05 pid:69609 ERROR: cllConnect: [unixODBC]FATAL:  sorry, too many clients already


I was previously running the same multithreaded application (closeAndEatExceptions() not commented out) with Jargon-Core 3.0.0.1 w/out these issues.  I can roll back to that or 3.1.3 to see if I still have the same problems if you think that would be useful.  There were some API changes between 3.0.0.1 and 3.1.3 I believe.