Gents,

I've been trying to work out why it is that at certain customer sites the IPWS can become unresponsive and must be restarted before it can be used again. I can now see what's going on - it happens when send a request which never receives a response, no matter how long a timeout I allow. For instance, here's a case where GetFileDetails was responding happily and then stopped at 05:20:57.880:

2017-02-02 05:20:57.440 http-9090-Processor25 user.sdr        -- INPUT: GetFileDetailsType[interplayURIs={interplay://INTERPLAY-5?mobid=060a2b340101010101010f0013-000000-89beb725867705c3-08004602026b-8c6a}]
2017-02-02 05:20:57.815 http-9090-Processor25 user.sdr        -- OUTPUT: GetFileDetailsResponseType[numResults=1,numErrors=0]
2017-02-02 05:20:57.859 http-9090-Processor25 user.sdr        -- INPUT: SetAttributesType[interplayURIs={interplay://INTERPLAY-5?mobid=060a2b340101010101010f0013-000000-a0901427867705c2-08004602026b-8c6a},attributes={[group=USER,name=MatrixStore status,value=archive in progress 2/2/17 5:20 AM]}]
2017-02-02 05:20:57.879 http-9090-Processor25 user.sdr        -- OUTPUT: SetAttributesResponseType[numErrors=0]
2017-02-02 05:20:57.880 http-9090-Processor25 user.sdr        -- INPUT: GetFileDetailsType[interplayURIs={interplay://INTERPLAY-5?mobid=060a2b340101010101010f0013-000000-a0901427867705c2-08004602026b-8c6a}]
2017-02-02 05:22:19.398 http-9090-Processor24 user.sdr        -- INPUT: GetFileDetailsType[interplayURIs={interplay://INTERPLAY-5?mobid=060a2b340101010101010f0013-000000-a0901427867705c2-08004602026b-8c6a}]
2017-02-02 05:23:19.900 http-9090-Processor22 user.sdr        -- INPUT: GetFileDetailsType[interplayURIs={interplay://INTERPLAY-5?mobid=060a2b340101010101010f0013-000000-a0901427867705c2-08004602026b-8c6a}]
2017-02-02 05:24:20.402 http-9090-Processor23 user.sdr        -- INPUT: GetFileDetailsType[interplayURIs={interplay://INTERPLAY-5?mobid=060a2b340101010101010f0013-000000-a0901427867705c2-08004602026b-8c6a}]
2017-02-02 05:25:20.903 http-9090-Processor21 user.sdr        -- INPUT: GetFileDetailsType[interplayURIs={interplay://INTERPLAY-5?mobid=060a2b340101010101010f0013-000000-a0901427867705c2-08004602026b-8c6a}]
2017-02-02 05:26:21.404 http-9090-Processor20 user.sdr        -- INPUT: GetFileDetailsType[interplayURIs={interplay://INTERPLAY-5?mobid=060a2b340101010101010f0013-000000-a0901427867705c2-08004602026b-8c6a}]
2017-02-02 05:27:21.904 http-9090-Processor19 user.sdr        -- INPUT: GetFileDetailsType[interplayURIs={interplay://INTERPLAY-5?mobid=060a2b340101010101010f0013-000000-a0901427867705c2-08004602026b-8c6a}]
2017-02-02 05:28:22.406 http-9090-Processor17 user.sdr        -- INPUT: GetFileDetailsType[interplayURIs={interplay://INTERPLAY-5?mobid=060a2b340101010101010f0013-000000-a0901427867705c2-08004602026b-8c6a}]
2017-02-02 05:29:22.908 http-9090-Processor18 user.sdr        -- INPUT: GetFileDetailsType[interplayURIs={interplay://INTERPLAY-5?mobid=060a2b340101010101010f0013-000000-a0901427867705c2-08004602026b-8c6a}]
2017-02-02 05:30:23.409 http-9090-Processor16 user.sdr        -- INPUT: GetFileDetailsType[interplayURIs={interplay://INTERPLAY-5?mobid=060a2b340101010101010f0013-000000-a0901427867705c2-08004602026b-8c6a}]
2017-02-02 05:31:23.911 http-9090-Processor15 user.sdr        -- INPUT: GetFileDetailsType[interplayURIs={interplay://INTERPLAY-5?mobid=060a2b340101010101010f0013-000000-a0901427867705c2-08004602026b-8c6a}]
2017-02-02 05:32:24.411 http-9090-Processor14 user.sdr        -- INPUT: GetFileDetailsType[interplayURIs={interplay://INTERPLAY-5?mobid=060a2b340101010101010f0013-000000-a0901427867705c2-08004602026b-8c6a}]
2017-02-02 05:33:24.913 http-9090-Processor12 user.sdr        -- INPUT: GetFileDetailsType[interplayURIs={interplay://INTERPLAY-5?mobid=060a2b340101010101010f0013-000000-a0901427867705c2-08004602026b-8c6a}]
2017-02-02 05:34:25.413 http-9090-Processor13 user.sdr        -- INPUT: GetFileDetailsType[interplayURIs={interplay://INTERPLAY-5?mobid=060a2b340101010101010f0013-000000-a0901427867705c2-08004602026b-8c6a}]
2017-02-02 05:35:25.915 http-9090-Processor11 user.sdr        -- INPUT: GetFileDetailsType[interplayURIs={interplay://INTERPLAY-5?mobid=060a2b340101010101010f0013-000000-a0901427867705c2-08004602026b-8c6a}]
2017-02-02 05:36:26.415 http-9090-Processor10 user.sdr        -- INPUT: GetFileDetailsType[interplayURIs={interplay://INTERPLAY-5?mobid=060a2b340101010101010f0013-000000-a0901427867705c2-08004602026b-8c6a}]
2017-02-02 05:37:26.916 http-9090-Processor9 user.sdr        -- INPUT: GetFileDetailsType[interplayURIs={interplay://INTERPLAY-5?mobid=060a2b340101010101010f0013-000000-a0901427867705c2-08004602026b-8c6a}]
2017-02-02 05:38:27.418 http-9090-Processor8 user.sdr        -- INPUT: GetFileDetailsType[interplayURIs={interplay://INTERPLAY-5?mobid=060a2b340101010101010f0013-000000-a0901427867705c2-08004602026b-8c6a}]
2017-02-02 05:39:27.919 http-9090-Processor7 user.sdr        -- INPUT: GetFileDetailsType[interplayURIs={interplay://INTERPLAY-5?mobid=060a2b340101010101010f0013-000000-a0901427867705c2-08004602026b-8c6a}]
2017-02-02 05:40:28.420 http-9090-Processor6 user.sdr        -- INPUT: GetFileDetailsType[interplayURIs={interplay://INTERPLAY-5?mobid=060a2b340101010101010f0013-000000-a0901427867705c2-08004602026b-8c6a}]
2017-02-02 05:41:28.921 http-9090-Processor5 user.sdr        -- INPUT: GetFileDetailsType[interplayURIs={interplay://INTERPLAY-5?mobid=060a2b340101010101010f0013-000000-a0901427867705c2-08004602026b-8c6a}]
2017-02-02 05:42:29.422 http-9090-Processor4 user.sdr        -- INPUT: GetFileDetailsType[interplayURIs={interplay://INTERPLAY-5?mobid=060a2b340101010101010f0013-000000-a0901427867705c2-08004602026b-8c6a}]
2017-02-02 05:43:29.924 http-9090-Processor3 user.sdr        -- INPUT: GetFileDetailsType[interplayURIs={interplay://INTERPLAY-5?mobid=060a2b340101010101010f0013-000000-a0901427867705c2-08004602026b-8c6a}]
2017-02-02 05:44:30.426 http-9090-Processor2 user.sdr        -- INPUT: GetFileDetailsType[interplayURIs={interplay://INTERPLAY-5?mobid=060a2b340101010101010f0013-000000-a0901427867705c2-08004602026b-8c6a}]

My strategy for coping when a request times out is simply to keep sending the same request every minute, which is doomed to fail in this case because the WS just keeps allocating new HTTP processors and eventually runs out of resources. It even stops writing its log - the line at 05:44:30.426 was the last thing it wrote.

In the above case, the underlying error is apparent from the iws_ log:

2017-02-02 05:17:21.129 [INFO ] http-9090-Processor25 user.sdr        c.a.i.w.a.d.JXDKCheckInOutDAO      :441   -- Checked out file to: C:\Program Files (x86)\Avid\Interplay Web Services\apache-tomcat\temp\060a2b340101010101010f0013-000000-4b4b4934867705c0-08004602026b-8c6a7322260159499733313tmp
2017-02-02 05:17:38.770 [INFO ] http-9090-Processor25 user.sdr        c.a.i.w.a.dao.JXDKAvidAssetDAO     :656   -- GetFileDetails UpdateStatus return:Could not contact Media Indexer for Workgroup 'INTERPLA-5' because the Lookup Service could not be found.
2017-02-02 05:17:49.090 [INFO ] http-9090-Processor25 user.sdr        c.a.i.w.a.dao.JXDKAvidAssetDAO     :656   -- GetFileDetails UpdateStatus return:Could not contact Media Indexer for Workgroup 'INTERPLA-5' because the Lookup Service could not be found.
2017-02-02 05:17:59.456 [INFO ] http-9090-Processor25 user.sdr        c.a.i.w.a.dao.JXDKAvidAssetDAO     :656   -- GetFileDetails UpdateStatus return:Could not contact Media Indexer for Workgroup 'INTERPLA-5' because the Lookup Service could not be found.
2017-02-02 05:18:09.843 [INFO ] http-9090-Processor25 user.sdr        c.a.i.w.a.dao.JXDKAvidAssetDAO     :656   -- GetFileDetails UpdateStatus return:Could not contact Media Indexer for Workgroup 'INTERPLA-5' because the Lookup Service could not be found.
2017-02-02 05:18:20.212 [INFO ] http-9090-Processor25 user.sdr        c.a.i.w.a.dao.JXDKAvidAssetDAO     :656   -- GetFileDetails UpdateStatus return:Could not contact Media Indexer for Workgroup 'INTERPLA-5' because the Lookup Service could not be found.
2017-02-02 05:18:30.653 [INFO ] http-9090-Processor25 user.sdr        c.a.i.w.a.dao.JXDKAvidAssetDAO     :656   -- GetFileDetails UpdateStatus return:Could not contact Media Indexer for Workgroup 'INTERPLA-5' because the Lookup Service could not be found.
2017-02-02 05:18:41.038 [INFO ] http-9090-Processor25 user.sdr        c.a.i.w.a.dao.JXDKAvidAssetDAO     :656   -- GetFileDetails UpdateStatus return:Could not contact Media Indexer for Workgroup 'INTERPLA-5' because the Lookup Service could not be found.
2017-02-02 05:18:51.402 [INFO ] http-9090-Processor25 user.sdr        c.a.i.w.a.dao.JXDKAvidAssetDAO     :656   -- GetFileDetails UpdateStatus return:Could not contact Media Indexer for Workgroup 'INTERPLA-5' because the Lookup Service could not be found.
2017-02-02 05:19:01.725 [INFO ] http-9090-Processor25 user.sdr        c.a.i.w.a.dao.JXDKAvidAssetDAO     :656   -- GetFileDetails UpdateStatus return:Could not contact Media Indexer for Workgroup 'INTERPLA-5' because the Lookup Service could not be found.
2017-02-02 05:19:12.196 [INFO ] http-9090-Processor25 user.sdr        c.a.i.w.a.dao.JXDKAvidAssetDAO     :656   -- GetFileDetails UpdateStatus return:Could not contact Media Indexer for Workgroup 'INTERPLA-5' because the Lookup Service could not be found.
2017-02-02 05:19:22.634 [INFO ] http-9090-Processor25 user.sdr        c.a.i.w.a.dao.JXDKAvidAssetDAO     :656   -- GetFileDetails UpdateStatus return:Could not contact Media Indexer for Workgroup 'INTERPLA-5' because the Lookup Service could not be found.
2017-02-02 05:19:33.079 [INFO ] http-9090-Processor24 user.sdr        c.a.i.w.a.dao.JXDKAvidAssetDAO     :656   -- GetFileDetails UpdateStatus return:Could not contact Media Indexer for Workgroup 'INTERPLA-5' because the Lookup Service could not be found.
2017-02-02 05:19:43.529 [INFO ] http-9090-Processor24 user.sdr        c.a.i.w.a.dao.JXDKAvidAssetDAO     :656   -- GetFileDetails UpdateStatus return:Could not contact Media Indexer for Workgroup 'INTERPLA-5' because the Lookup Service could not be found.
2017-02-02 05:19:53.972 [INFO ] http-9090-Processor24 user.sdr        c.a.i.w.a.dao.JXDKAvidAssetDAO     :656   -- GetFileDetails UpdateStatus return:Could not contact Media Indexer for Workgroup 'INTERPLA-5' because the Lookup Service could not be found.
2017-02-02 05:20:04.461 [INFO ] http-9090-Processor24 user.sdr        c.a.i.w.a.dao.JXDKAvidAssetDAO     :656   -- GetFileDetails UpdateStatus return:Could not contact Media Indexer for Workgroup 'INTERPLA-5' because the Lookup Service could not be found.
2017-02-02 05:20:14.903 [INFO ] http-9090-Processor24 user.sdr        c.a.i.w.a.dao.JXDKAvidAssetDAO     :656   -- GetFileDetails UpdateStatus return:Could not contact Media Indexer for Workgroup 'INTERPLA-5' because the Lookup Service could not be found.
2017-02-02 05:20:25.352 [INFO ] http-9090-Processor24 user.sdr        c.a.i.w.a.dao.JXDKAvidAssetDAO     :656   -- GetFileDetails UpdateStatus return:Could not contact Media Indexer for Workgroup 'INTERPLA-5' because the Lookup Service could not be found.
2017-02-02 05:20:56.897 [INFO ] http-9090-Processor25 user.sdr        c.a.i.w.a.dao.JXDKAvidAssetDAO     :656   -- GetFileDetails UpdateStatus return:Could not contact Media Indexer for Workgroup 'INTERPLA-5' because the Lookup Service could not be found.
2017-02-02 05:20:57.458 [INFO ] http-9090-Processor25 user.sdr        c.a.i.w.a.dao.JXDKAvidAssetDAO     :656   -- GetFileDetails UpdateStatus return:null

The final "null" implies to me that the thread dealing with the request hit a NullPointerException and simply died without ever responding, which is bad news.

The above is happening with IPWS 3.0.5. However, I just had a similar thing happen on my own system using IPWS 2.7.5, except in this case it was a GetAttributes request that never got a response, and the iws_ log shows nothing untoward.

So I'll change my strategy for coping with timeouts, by repeating the same request asynchronously. If I judge that the WS will never respond, I'll probably restart the Windows service programmatically if I can, because there seems to be no other way out of this situation.

Geoff.

Hi Geoff,

Please use an up to date version of IPWS that is suitable for your Interplay environment. A lot of errors has been fixed in the newer versions.

The error log you have clearly specifies connection issues with Media Indexer which may be a result of network issues, non matching IPWS version or old versions of IPWS running out of memory. This is a known issues that has been fixed in later releases.

Thanks,

Vadym

Hi Vadym,

The logs I shared with you are from a customer using IPWS 3.4.0, which is the same their Interplay engine. Digging into it further, I found that the WS actually did send a reply of sorts, but it was empty, giving this XML parsing message:

com.ctc.wstx.exc.WstxEOFException: Unexpected EOF in prolog at [row,col {unknown-source}]: [1,0]

Geoff.