Adapter Listener startup Problem

, ,
1

Hi All,

I am using a custom Adapter which has been deployed in the IS.

I have configured Listeners from the IS Admin GUI—> Adapter GUI. but I am getting one problem.

When I restart the IS server, the listeners that was configured were disabled. ( the enabled tab was coming as “No” and the status tab was coming as “Succeeded”) . I am able to manually enable them. ( by clicking on the “No” ).

Is it possible to autommatically enable the listener as soon as the IS server is started… Is some sort of trigger mechanism required in the custom Adapter implementation to automaticaly enable the listener.

I am very new to the webMethods world…(a few days old :slight_smile: ). Please, if anyone could help me out, it would be greatly appreciated.

Thanks.

Regards,
Charles

2

Check the error logs to see if some error, like a dependency of some sort, is causing the startup of the adapter to fail.

3

Hi ,

Thanks for the suggestion.

In the error logs, there is no error coming and in the Server logs, I can see clearly that the Adapter is being started.

The logs comes like as given below. ( My adapter name is ProvidentAdapter).

2007-05-10 13:31:37 BST [ISS.0025.0001C] Integration Server 6.1 Build 132
2007-05-10 13:31:37 BST [ISS.0025.0006C] License Manager started
2007-05-10 13:31:37 BST [ISS.0025.0041C] FIPS mode not initialized
2007-05-10 13:31:38 BST [ISS.0025.0017C] Repository Manager started
2007-05-10 13:31:44 BST [ISS.0025.0024C] JDBC Connection Manager started
2007-05-10 13:31:48 BST [ISS.0025.0023C] Audit Log Manager started
2007-05-10 13:31:49 BST [ISS.0025.0021C] ACL Manager started
2007-05-10 13:31:49 BST [ISS.0025.0008C] State Manager started
2007-05-10 13:31:51 BST [ISS.0025.0010C] Service Manager started
2007-05-10 13:31:51 BST [ISS.0025.0020C] Validation Processor started
2007-05-10 13:31:51 BST [ISS.0025.0022C] Statistics Processor started
2007-05-10 13:31:51 BST [ISS.0025.0018C] Invoke Manager started
2007-05-10 13:31:52 BST [ISS.0025.0012C] Cache Manager started
2007-05-10 13:31:53 BST [ISS.0098.0026D] Document Store DefaultStore initialized
2007-05-10 13:31:54 BST [ISS.0098.0026D] Document Store VolatileTriggerStore initialized
2007-05-10 13:31:54 BST [ISS.0098.0026D] Document Store TriggerStore initialized
2007-05-10 13:31:54 BST [ISS.0098.0026D] Document Store ResubmitStore initialized
2007-05-10 13:31:55 BST [ISS.0106.0001D] Join Manager initialized
2007-05-10 13:31:55 BST [ISS.0025.0032C] Dispatcher initialized
2007-05-10 13:31:55 BST [ISS.0025.0004C] Flow Service Manager started
2007-05-10 13:31:55 BST [ISS.0025.0002C] Package Manager started
2007-05-10 13:31:55 BST [ISS.0025.0011C] Package Replicator Manager started
2007-05-10 13:31:55 BST [ISS.0028.0001C] Loading packages
2007-05-10 13:31:59 BST [ISS.0028.0005C] Loading WmRoot package
2007-05-10 13:32:07 BST [ISS.0028.0005C] Loading WmPublic package
2007-05-10 13:32:08 BST [ISS.0028.0005C] Loading WmOmiAgent package
2007-05-10 13:32:08 BST [ISS.0028.0005C] Loading WmOmiIs package
2007-05-10 13:32:09 BST [ISS.0028.0005C] Loading WmART package

2007-05-10 13:32:09 BST [ISS.0028.0005C] Loading ProvidentAdapter package

2007-05-10 13:32:10 BST [ISS.0028.0005C] Loading VFTertioSample package
2007-05-10 13:32:10 BST [ISS.0028.0005C] Loading Default package

2007-05-10 13:32:10 BST [ISS.0028.0005C] Loading TestProvident package

2007-05-10 13:32:10 BST [ISS.0028.0012C] WmRoot: Startup service (wm.server.event:startEventAgentPort)
2007-05-10 13:32:10 BST [ISS.0028.0012C] WmRoot: Startup service (wm.server.net.email:init)
2007-05-10 13:32:10 BST [ISS.0028.0012C] WmRoot: Startup service (wm.server.net.ftp:init)
2007-05-10 13:32:10 BST [ISS.0028.0012C] WmRoot: Startup service (wm.server.net.http:init)
2007-05-10 13:32:10 BST [ISS.0028.0012C] WmRoot: Startup service (wm.server.net.https:init)
2007-05-10 13:32:10 BST [ISS.0028.0012C] WmRoot: Startup service (wm.server.net.sock:init)
2007-05-10 13:32:10 BST [ISS.0028.0012C] WmRoot: Startup service (wm.server.net.sslsock:init)
2007-05-10 13:32:10 BST [ISS.0028.0012C] WmRoot: Startup service (wm.server.ns:syncToNamespace)
2007-05-10 13:32:13 BST [ISS.0028.0012C] WmRoot: Startup service (wm.server.remote:init)
2007-05-10 13:32:13 BST [ISS.0028.0012C] WmRoot: Startup service (wm.server.schedule:init)
2007-05-10 13:32:13 BST [ISS.0028.0012C] WmRoot: Startup service (wm.server.dispatcher:init)
2007-05-10 13:32:13 BST [ISS.0028.0012C] WmRoot: Startup service (wm.server.security.revInvoke:init)
2007-05-10 13:32:13 BST [ISS.0028.0012C] WmRoot: Startup service (wm.server.tx:init)
2007-05-10 13:32:13 BST [ISC.0063.0011C] Start
2007-05-10 13:32:13 BST [ISS.0028.0012C] WmRoot: Startup service (wm.server.soap:init)
2007-05-10 13:32:13 BST [ISS.0028.0012C] WmRoot: Startup service (wm.server.dbalias:initRepoAlias)
2007-05-10 13:32:13 BST [ISS.0028.0012C] WmPublic: Startup service (pub.ldap:init)
2007-05-10 13:32:13 BST [ISS.0028.0012C] WmOmiAgent: Startup service (wm.ism.agent.pkginit:init)
2007-05-10 13:32:13 BST [ISS.0028.0012C] WmOmiIs: Startup service (omi.wm.is.pkginit:init)
2007-05-10 13:32:13 BST [ISS.0028.0012C] WmART: Startup service (wm.art.admin:startup)
2007-05-10 13:32:14 BST [ISS.0028.0012C] WmART: Startup service (omi.wm.art.ARTMbeanInit:init)

2007-05-10 13:32:14 BST [ISS.0028.0012C] ProvidentAdapter: Startup service (com.tertio.vodafonekk.webMethods.ProvidentAdapterAdmin:startUp)

2007-05-10 13:32:14 BST [ART.0114.1100D] Adapter Runtime: Facility 9000 - ProvidentAdapter registered with bundle com.tertio.vodafonekk.webMethods.ProvidentAdapterResourceBundle.

2007-05-10 13:32:14 BST [ADA.9000.0999D] Debug Message: ProvidentAdapter:initialize()
2007-05-10 13:32:14 BST [ADA.9000.0999D] Debug Message: ProvidentConnection constructor - Prov=telhp6:15898, Connect timeout=20000, Message timeout=20000

2007-05-10 13:32:14 BST [ADA.9000.0142I] Connected on port 55263 to Provident host telhp6, port 15898

2007-05-10 13:32:14 BST [SCC.0126.0001E] SCC ConnectionManager Pool Started

2007-05-10 13:32:14 BST [ADA.9000.0999D] Debug Message: ProvidentConnection constructor - Prov=telhp6:15899, Connect timeout=20000, Message timeout=15000

2007-05-10 13:32:14 BST [ADA.9000.0142I] Connected on port 55265 to Provident host telhp6, port 15899

2007-05-10 13:32:14 BST [SCC.0126.0001E] SCC ConnectionManager Pool Started
2007-05-10 13:32:14 BST [ISS.0098.0021D] Persistent Trigger Output Dispatcher started
2007-05-10 13:32:14 BST [ISS.0098.0021D] Volatile Trigger Output Dispatcher started
2007-05-10 13:32:14 BST [ISS.0098.0027D] PersistenceManager started all Stores
2007-05-10 13:32:14 BST [ISS.0025.0036C] Dispatcher started
2007-05-10 13:32:14 BST [ISS.0025.0005C] Port Manager started
2007-05-10 13:32:15 BST [ISS.0025.0013C] Cache Sweeper started
2007-05-10 13:32:15 BST [ISS.0014.0002C] Initialization completed in 42 seconds.
2007-05-10 13:32:15 BST [ISS.0025.0016C] Config File Directory Saved

2007-05-10 13:32:16 BST [ADA.9000.0999D] Debug Message: Entering ProvidentListener constructor

2007-05-10 13:33:06 BST [ADA.9000.0114D] In adapterResourceDomainLookup with serviceName com.tertio.vodafonekk.webMethods.notification.ProvidentSyncListenerNotification; domainName inputParameterNames
2007-05-10 13:33:06 BST [ADA.9000.0114D] In adapterResourceDomainLookup with serviceName com.tertio.vodafonekk.webMethods.notification.ProvidentSyncListenerNotification; domainName outputParameterNames
2007-05-10 13:33:09 BST [ADA.9000.0114D] In adapterResourceDomainLookup with serviceName com.tertio.vodafonekk.webMethods.notification.ProvidentSyncListenerNotification; domainName inputParameterNames
2007-05-10 13:33:09 BST [ADA.9000.0114D] In adapterResourceDomainLookup with serviceName com.tertio.vodafonekk.webMethods.notification.ProvidentSyncListenerNotification; domainName outputParameterNames

As seen above, I am assuming that the adapter started ( from the lines in bold). Then it is making connections to a server host and port.

After the connection establishment, then it is entering the custom Listener constructor. ( from the trace "Entering ProvidentListener constructor" ).

Then, it should call the overwritten listenerStartup() method which I think will enable the Listener “Enable” tab to “Yes” in the IS Admin GUI —> Adapter GUI. But , the IS server is not calling it …

In the Adapter GUI, I am getting all the other links like the connections, listener notifications etc… with the “Enable” tab set to “Yes” automatically. But only for the listener, I am not getting so.

Please could you guide me in this…

I would like to know whether we can set up the custom adapter startup sequence using some config file or something so that when the IS invokes the Adapter startup service, it ( IS) can know what are the things to be started up and in what sequence.

Basically , I want that the Listener “enabled” tab is automatically set to “Yes” in the Adapter GUI after the IS starts up.

Thanks.

4

Hi,

I’ve never used, but there is a service (pub.art.listener:enableListener) that may help.

It sounds more like a workarround, but you could invoke this service on package startup if it does what it promises.

Daniel

5

Hi,

Thanks for the reply…

But I am not sure how to invoke the said service on package startup…

Could you please guide me on that.

(I am now five days old in this webMethods world :slight_smile: )

Thanks again.

Charles.

6

Hi All,

I got some more clues on the above problem …Still could not solve it…

When I manually enabled the listeners, I am getiing a series of “Socket Timeout” after which the previous connection on the port was destroyed and a new connection on a new port was established.

When I restart the IS server, I am atleast able to get one listener automatically to “Yes” while the remaining other two listeners will be disabled. For this case also, the IS server has to be restarted at a paritcular point. (Please see below in the traces…)

MANUALLY ENABLED

2007-05-15 08:33:36 BST [ADA.9000.0999D] Debug Message: Entering ProvidentListener:listenerStartup()

2007-05-15 08:33:39 BST [ADA.9000.0999D] Debug Message: Entering ProvidentListener:listenerStartup()

2007-05-15 08:33:44 BST [ADA.9000.0999D] Debug Message: Entering ProvidentListener:listenerStartup()

Once all listeners are started, the “Socket Timeout” occurs every 20 ms.

2007-05-15 08:33:56 BST [ADA.9000.0153D] Socket timeout
2007-05-15 08:33:56 BST [ADA.9000.0141I] Destroying Connection on port : 60184 to Provident port 29818
2007-05-15 08:33:56 BST [ADA.9000.0142I] Connected on port 60432 to Provident host tsshp1, port 29818
2007-05-15 08:33:56 BST [ADA.9000.1010I] Error reading Connection on port 60432 to Provident port 29818 - java.io.EOFException
2007-05-15 08:33:56 BST [ADA.9000.0141I] Destroying Connection on port : 60432 to Provident port 29818

The above is not yet connected even though it has been destroyed…Before this listener gets a new connection, the other remaining two listeners will have their connection destroyed and got new connections.( as seen below)

2007-05-15 08:33:59 BST [ADA.9000.0153D] Socket timeout
2007-05-15 08:33:59 BST [ADA.9000.0141I] Destroying Connection on port : 60186 to Provident port 29818
2007-05-15 08:33:59 BST [ADA.9000.0142I] Connected on port 60437 to Provident host tsshp1, port 29818

2007-05-15 08:34:04 BST [ADA.9000.0153D] Socket timeout
2007-05-15 08:34:04 BST [ADA.9000.0141I] Destroying Connection on port : 60187 to Provident port 29818
2007-05-15 08:34:04 BST [ADA.9000.0142I] Connected on port 60443 to Provident host tsshp1, port 29818

The below line is for the above connection establishment that was not yet connected :

If I restart the IS server here at this stage, then this listener will be automatically enabled after restart.

2007-05-15 08:34:16 BST [ADA.9000.0142I] Connected on port 60449 to Provident host tsshp1, port 29818

If I restart the IS server here , after the above connection is done, then the associated listener is not automatically enabled after restart.

Also, one more thing is that for those listeners for which the message “Connected on port to Provident host tsshp1, port 29818” is coming, if I restart the server, then I get a “Fatal Error” message for the listeners. (As shown below).

2007-05-15 08:58:48 BST [ISS.0014.0005C] Shutting down server. No valid key was found.
2007-05-15 08:58:48 BST [ISS.0028.0015C] ProvidentAdapter: Shutdown service
2007-05-15 08:58:48 BST [ADA.9000.0999D] Debug Message: Invoked ProvidentAdapter:cleanup()
2007-05-15 08:58:48 BST [ART.0114.1107D] Adapter Runtime: Facility 9000 - ProvidentAdapter removed.

2007-05-15 08:58:48 BST [ART.0118.5053E] Adapter Runtime (Connection): Unable to get a connection to resource connections:destAgentConn.

2007-05-15 08:58:48 BST [ART.0115.3258E] Adapter Runtime (Listener): Fatal error in listener connectionsDestListener2. See error log for details

2007-05-15 08:58:48 BST [ART.0115.3258E] Adapter Runtime (Listener): Fatal error in listener connectionsDestListener. See error log for details

Please see above that the Fatal error is coming for the two connections
“connectionsDestListener” and “connectionsDestListener2”. It is not coming for “connectionsDestListener1”. So after server restart, I am getting “connectionsDestListener1” as automatically enabled and the other two as disabled.

2007-05-15 08:58:48 BST [ART.0118.5053E] Adapter Runtime (Connection): Unable to get a connection to resource connections:destAgentConn.
2007-05-15 08:58:48 BST [ART.0118.5053E] Adapter Runtime (Connection): Unable to get a connection to resource connections:destAgentConn.

From the error logs, I am getting a lot of errors as shown below.

===============================================

,errorCode=118.5053,errorMessageArgs=[0]connections:destAgentConn,errorResourceBundleName=com.wm.pkg.art.i18n.resources.AdapterRuntimeResourceBundle
,detail=>>>BasicData:retryConnection=true<<<<<<
connections:destAgentConn
2007-05-15 08:58:48 BST WMERROR 1cc9c4b002ba11dcb88299f23c2c8376NULL
1cc9c4b002ba11dcb88299f23c2c83761179215928443 telhp6.tertio.com:5555
The pool doesn’t have a connection available for the request.
javax.resource.spi.ResourceAllocationException: The pool doesn’t have a connection available for the request.

notifications:LisNotific2
2007-05-15 08:58:48 BST WMERROR 9c809c5002b611dcb86999f23c2c8376NULL
9c809c5002b611dcb86999f23c2c83761179215928493 telhp6.tertio.com:5555
NULL java.lang.NullPointerException

===============================================
Then the Fatal error part for DestListener2.

connections:DestListener2
2007-05-15 08:58:48 BST WMERROR 1cd9551002ba11dcb88699f23c2c8376NULL
1cd9551002ba11dcb88699f23c2c83761179215928545 telhp6.tertio.com:5555
[ART.118.5053] Adapter Runtime (Connection): Unable to get a connection to resource connections:destAgentConn.
The pool doesn’t have a connection available for the request.

BasicData:message=null,date=Tue May 15 08:58:48 BST 2007,reason=The pool doesn’t have a connection available for the request.,
exceptionClass=javax.resource.spi.ResourceAllocationException,stack=javax.resource.spi.ResourceAllocationException:
The pool doesn’t have a connection available for the request.

================================================================================================================================
THE ABOVE PART WAS FOR DESTLISTNER2

The same error comes for DESTLISTENER

I am not sure what is happening out here…If anyone could please suggest something, please do… grately appreciated…

Charles.

7

Hi All,

Thanks for the support.

I have got the problem solved. It turned out to be a bug in the adapter code.

The waitForData() method that gets called by the IS when I manually start a listener was not at all throwing an AdapterConnectionException when an exception occurs.

Once a listener faces an exception, the old ports from the connection pooled were getting destroyed and then new ports were created and this was happening frequently.

This was the basic problem. I am able to automatically enable the listeners after IS restart now.

But I do seem to face a small minor problem.

I seem to get a java.lang.EOFException when I run the following sequence of events.

  1. Disable connection node.
  2. Disable the listener nodes dependent on this connection node.
  3. Enable the connection node.
  4. Enable any one listener node.

What then happens is that I get a java.lang.EOFException. So, the above step 4 fails,i.e, the listener fails to get enabled.

The IS then automatically retries to get the listener enabled. But everytime it becomes first enabled and then gets the same java.lang.EOFException and then gets disabled. Then, this process repeats for a configurable number of times.

If anyone could suggest anything to come around with this problem, please do.

I am setting the “Fatal” flag to false while throwing the AdapterConnectionException. Will setting the flag to true make any difference.

Thanks for all the help.

Cheers,
Charles.

8

hi all