Dear all,
for some reason, my OEM is corrupted and when it's enabled, it messes up with the listener. I concluded the problem lies in OEM rather than in the listener since I can establish connection between SQLdeveloper and the server via the listener without any problem.
I have instance named INARA, host named FIREFLY.SNOWDROP.COM, and listener named ORACLE_LISTENER.
I closed SQLdeveloper application and its listener and started OEM first to pinpoint the problem. After I started OEM, the Management Service log emoms.log dumped:
2011-06-15 11:55:12,203 [HTTPThreadGroup-2] WARN jdbc.ConnectionCache _getConnection.353 - Got a fatal exeption when getting a connection; Error code = 17002; Cleaning up cache and retrying
2011-06-15 11:55:12,204 [HTTPThreadGroup-2] ERROR conn.ConnectionService verifyRepositoryEx.891 - Invalid Connection Pool. ERROR = Io exception: The Network Adapter could not establish the connection
2011-06-15 11:55:12,205 [EMUI_11_55_12_/console/aboutApplication] ERROR svlt.PageHandler handleRequest.639 - java.lang.IllegalStateException: Response has already been committed
java.lang.IllegalStateException: Response has already been committed
at com.evermind.server.http.EvermindHttpServletResponse.resetBuffer(EvermindHttpServletResponse.java:1892)
at com.evermind.server.http.ServletRequestDispatcher.unprivileged_forward(ServletRequestDispatcher.java:249)
at com.evermind.server.http.ServletRequestDispatcher.access$100(ServletRequestDispatcher.java:51)
at com.evermind.server.http.ServletRequestDispatcher$2.oc4jRun(ServletRequestDispatcher.java:193)
at oracle.oc4j.security.OC4JSecurity.doPrivileged(OC4JSecurity.java:284)
at com.evermind.server.http.ServletRequestDispatcher.forward(ServletRequestDispatcher.java:198)
at oracle.sysman.emSDK.svlt.PageHandler.render(PageHandler.java:1113)
at oracle.sysman.emSDK.svlt.PageHandler.myRender(PageHandler.java:1173)
at oracle.sysman.emSDK.svlt.PageHandler.handleRequest(PageHandler.java:597)
at oracle.sysman.emSDK.svlt.EMServlet.myDoGet(EMServlet.java:787)
at oracle.sysman.emSDK.svlt.EMServlet.doGet(EMServlet.java:343)
at oracle.sysman.eml.app.Console.doGet(Console.java:157)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:743)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:856)
at com.evermind.server.http.ResourceFilterChain.doFilter(ResourceFilterChain.java:64)
at oracle.sysman.eml.app.EMRepLoginFilter.doFilter(EMRepLoginFilter.java:107)
at com.evermind.server.http.EvermindFilterChain.doFilter(EvermindFilterChain.java:15)
at oracle.sysman.db.adm.inst.HandleRepDownFilter.doFilter(HandleRepDownFilter.java:146)
at com.evermind.server.http.EvermindFilterChain.doFilter(EvermindFilterChain.java:17)
at oracle.sysman.eml.app.BrowserVersionFilter.doFilter(BrowserVersionFilter.java:122)
at com.evermind.server.http.EvermindFilterChain.doFilter(EvermindFilterChain.java:17)
at oracle.sysman.emSDK.svlt.EMRedirectFilter.doFilter(EMRedirectFilter.java:102)
at com.evermind.server.http.EvermindFilterChain.doFilter(EvermindFilterChain.java:17)
at oracle.sysman.eml.app.ContextInitFilter.doFilter(ContextInitFilter.java:327)
at com.evermind.server.http.ServletRequestDispatcher.invoke(ServletRequestDispatcher.java:621)
at com.evermind.server.http.ServletRequestDispatcher.forwardInternal(ServletRequestDispatcher.java:370)
at com.evermind.server.http.HttpRequestHandler.doProcessRequest(HttpRequestHandler.java:871)
at com.evermind.server.http.HttpRequestHandler.processRequest(HttpRequestHandler.java:453)
at com.evermind.server.http.HttpRequestHandler.serveOneRequest(HttpRequestHandler.java:221)
at com.evermind.server.http.HttpRequestHandler.run(HttpRequestHandler.java:122)
at com.evermind.server.http.HttpRequestHandler.run(HttpRequestHandler.java:111)
at oracle.oc4j.network.ServerSocketReadHandler$SafeRunnable.run(ServerSocketReadHandler.java:260)
at oracle.oc4j.network.ServerSocketAcceptHandler.procClientSocket(ServerSocketAcceptHandler.java:234)
at oracle.oc4j.network.ServerSocketAcceptHandler.access$700(ServerSocketAcceptHandler.java:29)
at oracle.oc4j.network.ServerSocketAcceptHandler$AcceptHandlerHorse.run(ServerSocketAcceptHandler.java:879)
at com.evermind.util.ReleasableResourcePooledExecutor$MyWorker.run(ReleasableResourcePooledExecutor.java:303)
at java.lang.Thread.run(Thread.java:595)
also the Management Agent trace file emagent.trc dumped:
SQL = " OCISessionGet"...
LOGIN = dbsnmp/<PW>@(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=firefly.snowdrop.com)(PORT=1521))(CONNECT_DATA=(SID=inara)))
2011-06-15 11:57:05,914 Thread-4147767632 ERROR vpxoci: ORA-12541: TNS:no listener
2011-06-15 11:57:05,914 Thread-4147767632 WARN vpxoci: Login 0x67fd70 failed, error=ORA-12541: TNS:no listener
2011-06-15 11:57:05,914 Thread-4147767632 WARN TargetManager: Exception in computing dynamic properties of {inara.snowdrop.com, oracle_database },GetDbBlockSize::ORA-12541: TNS:no listener
2011-06-15 11:57:05,916 Thread-4138318160 ERROR TargetManager: nmeetm.c : Target inara.snowdrop.com has a failed critical dynamic property
2011-06-15 11:57:05,918 Thread-4138318160 WARN upload: Upload manager has no Failure script: disabled
2011-06-15 11:57:05,918 Thread-4138318160 WARN upload: Amount of upload data will be recalculated due to reload.enabling collections and regenerating metadata.
2011-06-15 11:57:05,918 Thread-4138318160 WARN TargetManager: Regenerating all Metadata
2011-06-15 11:57:05,983 Thread-4138318160 WARN upload: Truncating value of "SHORT_NAME" from "Average Synchronous Single-Block Read Latency (ms)" to "Average Synchronous Single-Block Read La"
2011-06-15 11:57:05,983 Thread-4138318160 WARN upload: Truncating value of "SHORT_NAME" from "Average Synchronous Single-Block Read Latency (ms)" to "Average Synchronous Single-Block Read La"
2011-06-15 11:57:06,080 Thread-4138318160 WARN upload: Truncating value of "COLUMN_LABEL" from "Total messages processed per queue per subscriber per minute in the last interval" to "Total messages processed per queue per subscriber per minute in "
2011-06-15 11:57:06,080 Thread-4138318160 WARN upload: Truncating value of "COLUMN_LABEL" from "Total messages received per queue per subscriber per minute in the last interval" to "Total messages received per queue per subscriber per minute in t"
2011-06-15 11:57:06,080 Thread-4138318160 WARN upload: Truncating value of "COLUMN_LABEL" from "Messages processed per queue (%) per subscriber per minute in the last interval" to "Messages processed per queue (%) per subscriber per minute in th"
2011-06-15 11:57:06,080 Thread-4138318160 WARN upload: Truncating value of "COLUMN_LABEL" from "Age of the first message in persistent queue per subscriber (seconds)" to "Age of the first message in persistent queue per subscriber (sec"
2011-06-15 11:57:06,081 Thread-4138318160 WARN upload: Truncating value of "COLUMN_LABEL" from "Age of the first message in the buffered queue per queue (seconds)" to "Age of the first message in the buffered queue per queue (second"
2011-06-15 11:57:06,096 Thread-4138318160 WARN collector: enable collector
2011-06-15 11:57:06,100 Thread-4138318160 WARN collector: Regenerating all DefaultColls
2011-06-15 11:57:07,145 Thread-4147767632 ERROR upload: Exceeded max. amount of upload data: 314 files, 346.533864 MB Data. 89.74% of disk used. Disabling collections.
2011-06-15 11:57:07,145 Thread-4147767632 WARN collector: Disable collector
2011-06-15 11:57:08,237 Thread-4147767632 ERROR pingManager: nmepm_pingReposURL: Did not receive a response header from repository
2011-06-15 11:57:08,337 Thread-4147767632 ERROR pingManager: nmepm_pingReposURL: Did not receive a response header from repository
2011-06-15 11:57:38,442 Thread-4147767632 ERROR pingManager: nmepm_pingReposURL: Did not receive a response header from repository
2011-06-15 11:57:38,545 Thread-4147767632 ERROR pingManager: nmepm_pingReposURL: Did not receive a response header from repository
2011-06-15 11:58:08,732 Thread-4138318160 ERROR pingManager: nmepm_pingReposURL: Did not receive a response header from repository
2011-06-15 11:58:08,835 Thread-4138318160 ERROR pingManager: nmepm_pingReposURL: Did not receive a response header from repository
2011-06-15 11:58:38,952 Thread-4138318160 ERROR pingManager: nmepm_pingReposURL: Did not receive a response header from repository
2011-06-15 11:58:39,055 Thread-4138318160 ERROR pingManager: nmepm_pingReposURL: Did not receive a response header from repository
2011-06-15 11:59:09,157 Thread-4138318160 ERROR pingManager: nmepm_pingReposURL: Did not receive a response header from repository
2011-06-15 11:59:09,260 Thread-4138318160 ERROR pingManager: nmepm_pingReposURL: Did not receive a response header from repository
2011-06-15 11:59:39,364 Thread-4138318160 ERROR pingManager: nmepm_pingReposURL: Did not receive a response header from repository
2011-06-15 11:59:39,465 Thread-4138318160 ERROR pingManager: nmepm_pingReposURL: Did not receive a response header from repository
2011-06-15 11:59:58,595 Thread-4154857808 ERROR command: nmejcn: received no status header from repository at https://firefly.snowdrop.com:5500/em/upload/
Looked like OEM had some errors and warnings after it got initiated but I don't know what they meant.
After OEM is successfully started, at least according to the emtcl command, I started listener ORACLE_LISTENER. At this point I performed loopback test using NET manager on the server, and it took forever so I aborted it. The database at this point was still open and running without problem though. TNSPING took 157080 msc to return OK value, on the other hand lsnrctl status ORACLE_STATUS was stalled.
So looking at emagent.trc after listener was initiated:
2011-06-15 12:02:10,306 Thread-4138318160 WARN ssl: <nmehlssl.c:nmehlssl_readcb>: nmehl_read_sock timed out, rsf = -5, setting read timeout flag
2011-06-15 12:02:10,306 Thread-4138318160 WARN ssl.io: fd=6: nmehlssl_read, nzos_Read error = 28862 readTimed Out = 1
2011-06-15 12:02:10,306 Thread-4138318160 WARN http: <nmehl.c>:<nmehl_readline>: nmehlssl_read() timed out
2011-06-15 12:02:10,306 Thread-4138318160 ERROR pingManager: nmepm_pingReposURL: Error in request response. code = 400. text =
2011-06-15 12:02:40,433 Thread-4138318160 WARN ssl: <nmehlssl.c:nmehlssl_readcb>: nmehl_read_sock timed out, rsf = -5, setting read timeout flag
2011-06-15 12:02:40,433 Thread-4138318160 WARN ssl.io: fd=6: nmehlssl_read, nzos_Read error = 28862 readTimed Out = 1
2011-06-15 12:02:40,433 Thread-4138318160 WARN http: <nmehl.c>:<nmehl_readline>: nmehlssl_read() timed out
2011-06-15 12:02:40,433 Thread-4138318160 ERROR pingManager: nmepm_pingReposURL: Error in request response. code = 400. text =
2011-06-15 12:03:40,570 Thread-4138318160 WARN ssl: <nmehlssl.c:nmehlssl_readcb>: nmehl_read_sock timed out, rsf = -5, setting read timeout flag
2011-06-15 12:03:40,570 Thread-4138318160 WARN ssl.io: fd=6: nmehlssl_read, nzos_Read error = 28862 readTimed Out = 1
2011-06-15 12:03:40,570 Thread-4138318160 WARN http: <nmehl.c>:<nmehl_readline>: nmehlssl_read() timed out
2011-06-15 12:03:40,570 Thread-4138318160 ERROR pingManager: nmepm_pingReposURL: Error in request response. code = 400. text =
2011-06-15 12:04:10,704 Thread-4138318160 WARN ssl: <nmehlssl.c:nmehlssl_readcb>: nmehl_read_sock timed out, rsf = -5, setting read timeout flag
2011-06-15 12:04:10,704 Thread-4138318160 WARN ssl.io: fd=6: nmehlssl_read, nzos_Read error = 28862 readTimed Out = 1
2011-06-15 12:04:10,704 Thread-4138318160 WARN http: <nmehl.c>:<nmehl_readline>: nmehlssl_read() timed out
2011-06-15 12:04:10,704 Thread-4138318160 ERROR pingManager: nmepm_pingReposURL: Error in request response. code = 400. text =
also emoms.trc
2011-06-15 12:05:26,159 [HTTPThreadGroup-6] WARN jdbc.ConnectionCache _getConnection.353 - Got a fatal exeption when getting a connection; Error code = 17002; Cleaning up cache and retrying
2011-06-15 12:05:29,774 [HTTPThreadGroup-5] WARN jdbc.ConnectionCache _getConnection.352 - Io exception: Socket read timed out
java.sql.SQLException: Io exception: Socket read timed out
at oracle.jdbc.driver.SQLStateMapping.newSQLException(SQLStateMapping.java:77)
at oracle.jdbc.driver.DatabaseError.newSQLException(DatabaseError.java:111)
at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:174)
at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:230)
at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:501)
at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:436)
at oracle.jdbc.driver.PhysicalConnection.<init>(PhysicalConnection.java:621)
at oracle.jdbc.driver.T4CConnection.<init>(T4CConnection.java:203)
at oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:34)
at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:492)
at oracle.jdbc.pool.OracleDataSource.getPhysicalConnection(OracleDataSource.java:386)
at oracle.jdbc.pool.OracleDataSource.getConnection(OracleDataSource.java:276)
at oracle.jdbc.pool.OracleConnectionPoolDataSource.getPhysicalConnection(OracleConnectionPoolDataSource.java:212)
at oracle.jdbc.pool.OracleConnectionPoolDataSource.getPooledConnection(OracleConnectionPoolDataSource.java:140)
at oracle.jdbc.pool.OracleImplicitConnectionCache.makeCacheConnection(OracleImplicitConnectionCache.java:1752)
at oracle.jdbc.pool.OracleImplicitConnectionCache.makeOneConnection(OracleImplicitConnectionCache.java:644)
at oracle.jdbc.pool.OracleImplicitConnectionCache.getCacheConnection(OracleImplicitConnectionCache.java:592)
at oracle.jdbc.pool.OracleImplicitConnectionCache.getConnection(OracleImplicitConnectionCache.java:460)
at oracle.jdbc.pool.OracleDataSource.getConnection(OracleDataSource.java:544)
at oracle.jdbc.pool.OracleDataSource.getConnection(OracleDataSource.java:480)
at oracle.sysman.util.jdbc.ConnectionCache._getConnection(ConnectionCache.java:336)
at oracle.sysman.util.jdbc.ConnectionCache._getConnection(ConnectionCache.java:322)
at oracle.sysman.util.jdbc.ConnectionCache.getUnwrappedConnection(ConnectionCache.java:575)
at oracle.sysman.emSDK.svc.conn.FGAConnectionCache.getFGAConnection(FGAConnectionCache.java:207)
at oracle.sysman.emSDK.svc.conn.ConnectionService.getPrivateConnection(ConnectionService.java:1138)
at oracle.sysman.emSDK.svc.conn.ConnectionService.getPrivateConnection(ConnectionService.java:1172)
at oracle.sysman.emdrep.receiver.OMSHandshake.getParameterFromDB(OMSHandshake.java:570)
at oracle.sysman.emdrep.receiver.OMSHandshake.getMaxAgentCompatVer(OMSHandshake.java:552)
at oracle.sysman.emdrep.receiver.OMSHandshake.handshake(OMSHandshake.java:1033)
at oracle.sysman.emdrep.receiver.OMSHandshake.handshake(OMSHandshake.java:836)
at oracle.sysman.emdrep.receiver.FxferRecv.doGet(FxferRecv.java:598)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:743)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:856)
at com.evermind.server.http.ResourceFilterChain.doFilter(ResourceFilterChain.java:64)
at oracle.sysman.eml.app.ContextInitFilter.doFilter(ContextInitFilter.java:327)
at com.evermind.server.http.ServletRequestDispatcher.invoke(ServletRequestDispatcher.java:623)
at com.evermind.server.http.ServletRequestDispatcher.forwardInternal(ServletRequestDispatcher.java:370)
at com.evermind.server.http.HttpRequestHandler.doProcessRequest(HttpRequestHandler.java:871)
at com.evermind.server.http.HttpRequestHandler.processRequest(HttpRequestHandler.java:453)
at com.evermind.server.http.HttpRequestHandler.serveOneRequest(HttpRequestHandler.java:221)
at com.evermind.server.http.HttpRequestHandler.run(HttpRequestHandler.java:122)
at com.evermind.server.http.HttpRequestHandler.run(HttpRequestHandler.java:111)
at oracle.oc4j.network.ServerSocketReadHandler$SafeRunnable.run(ServerSocketReadHandler.java:260)
at oracle.oc4j.network.ServerSocketAcceptHandler.procClientSocket(ServerSocketAcceptHandler.java:234)
at oracle.oc4j.network.ServerSocketAcceptHandler.access$700(ServerSocketAcceptHandler.java:29)
at oracle.oc4j.network.ServerSocketAcceptHandler$AcceptHandlerHorse.run(ServerSocketAcceptHandler.java:879)
at com.evermind.util.ReleasableResourcePooledExecutor$MyWorker.run(ReleasableResourcePooledExecutor.java:303)
at java.lang.Thread.run(Thread.java:595)
2011-06-15 12:05:29,775 [HTTPThreadGroup-5] WARN jdbc.ConnectionCache _getConnection.353 - Got a fatal exeption when getting a connection; Error code = 17002; Cleaning up cache and retrying
lastly, ORACLE_LISTENER log said:
15-JUN-2011 12:16:38 * <unknown connect data> * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.1.5)(PORT=18844)) * establish * <unknown sid> * 12525
TNS-12525: TNS:listener has not received client's request in time allowed
TNS-12535: TNS:operation timed out
TNS-12606: TNS: Application timeout occurred
15-JUN-2011 12:16:38 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=__jdbc__)(USER=oracle))(SERVICE_NAME=inara.snowdrop.com)) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.1.5)(PORT=18842)) * establish * inara.snowdrop.com * 0
15-JUN-2011 12:16:38 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=__jdbc__)(USER=oracle))(SERVICE_NAME=inara.snowdrop.com)) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.1.5)(PORT=18838)) * establish * inara.snowdrop.com * 0
15-JUN-2011 12:16:38 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=__jdbc__)(USER=oracle))(SERVICE_NAME=inara.snowdrop.com)) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.1.5)(PORT=18833)) * establish * inara.snowdrop.com * 0
15-JUN-2011 12:16:38 * service_update * inara * 0
15-JUN-2011 12:16:38 * service_update * inara * 0
15-JUN-2011 12:16:38 * service_update * inara * 0
At this point some part of the NET services was corrupted caused by OEM corruption, but I didn't know what caused of it. The NET services with its listener can work normally after I stopped OEM and forced killed the listener and restarted it normally.
Any idea how to troubleshoot the problem from this point?
regards,
Val