webMethods Knowlegebase : MFT: Error reusing Control socket handshake. java.lang.NullP (1805827)

Problem

Customer have a scenario where they upload the files to one of their agency FTPS server.

They have configured the virtual folder (Remote Path) with FTPS.

The connection is successful.

However while uploading the file to FTPS server through

Scheduled event, they get the below error.

Note: Below property also set.

mft.ssl.client.acceptAnyCert=false

2020-08-28 15:48:35,994 TRACE [com.softwareag.mft.external.session ][6961] - [EVENTLOGID:5cceg700egrk46cu00000009]Logging out the client[47,363,151] url:/

2020-08-28 15:48:35,994 TRACE [com.softwareag.mft.external.session ][6962] - [EVENTLOGID:5cceg700egrk46cu00000009]Client logout successfully completed. [47,363,151] url:/

2020-08-28 15:48:35,994 TRACE [com.softwareag.mft.external.session ][6957] - [EVENTLOGID:5cceg700egrk46cu00000009:Copy to FosterVision]Removing 0 clients from pool.

2020-08-28 15:48:35,995 TRACE [com.softwareag.mft.external.session ][6956] - [EVENTLOGID:5cceg700egrk46cu00000009:Copy to FosterVision]Closing the client due to exception. url:FTPS://***:***@ftp.fostervision.net:990/

2020-08-28 15:48:35,995 TRACE [com.softwareag.mft.external.session ][6961] - [EVENTLOGID:5cceg700egrk46cu00000009]Logging out the client[917,192,092] url:FTPS://***:***@ftp.fostervision.net:990/

2020-08-28 15:48:35,995 INFO [com.softwareag.mft.external.session.ftp ][0021] - [5cceg700egrk46cu00000009:PRISM_SCCPD_SCCOE.Copy to FosterVision:0:917192092] Input stream:java.io.BufferedReader@785d8163, read:450 TLS session of data connection has not resumed or the session does not match the control connection

2020-08-28 15:48:36,014 INFO [com.softwareag.mft.external.session.ftp ][0004] - [5cceg700egrk46cu00000009:PRISM_SCCPD_SCCOE.Copy to FosterVision:0:917192092] FTP Error! Expected 226 but got 450 TLS session of data connection has not resumed or the session does not match the control connection

Later we set this property too and now we are getting below error:

mft.client.ftpes.connection.data.sslreuse=true

2020-08-31 08:56:46,304 INFO [com.softwareag.mft.external.session.ftp ][0023] - [5cceg700eh2jl06i0000003m:PRISM_SCCPD_SCCOE.Copy to FosterVision:0:377937077] Output stream:java.io.BufferedWriter@2a9cc24c, written:PASV

2020-08-31 08:56:46,351 INFO [com.softwareag.mft.external.session.ftp ][0021] - [5cceg700eh2jl06i0000003m:PRISM_SCCPD_SCCOE.Copy to FosterVision:0:377937077] Input stream:java.io.BufferedReader@5a70092e, read:227 Entering Passive Mode (204,88,135,207,3,221)

2020-08-31 08:56:46,351 ERROR [com.softwareag.mft.external.session.ftp ][5055] - Error reusing Control socket handshake.

java.lang.NullPointerException: null

at com.softwareag.mft.client.FTPClient.prepareDataSocket(FTPClient.java:1786) [com.softwareag.mft.tunnel_10.5.0.0007-0795.jar:?]

at com.softwareag.mft.client.FTPClient.getTransferSocket(FTPClient.java:1668) [com.softwareag.mft.tunnel_10.5.0.0007-0795.jar:?]

at com.softwareag.mft.client.FTPClient.upload3(FTPClient.java:919) [com.softwareag.mft.tunnel_10.5.0.0007-0795.jar:?]

at com.softwareag.mft.client.GenericClient.upload3(GenericClient.java:744) [com.softwareag.mft.tunnel_10.5.0.0007-0795.jar:?]

at com.softwareag.mft.client.GenericClient.upload2(GenericClient.java:634) [com.softwareag.mft.tunnel_10.5.0.0007-0795.jar:?]

at com.softwareag.mft.client.GenericClient.upload(GenericClient.java:600) [com.softwareag.mft.tunnel_10.5.0.0007-0795.jar:?]

at com.softwareag.mft.client.GenericClient.upload(GenericClient.java:577) [com.softwareag.mft.tunnel_10.5.0.0007-0795.jar:?]

at com.softwareag.mft.activetask.plugins.CopyTask.doCopy(CopyTask.java:405) [activetask.jar:?]

at com.softwareag.mft.activetask.plugins.CopyTask.run(CopyTask.java:77) [activetask.jar:?]

at com.softwareag.mft.activetask.plugins.Task.go(Task.java:232) [activetask.jar:?]

at com.softwareag.mft.activetask.plugins.TaskExecutor.run(TaskExecutor.java:294) [activetask.jar:?]

at com.softwareag.mft.activetask.plugins.TaskExecutor.run(TaskExecutor.java:428) [activetask.jar:?]

at com.softwareag.mft.activetask.Start.doTasks(Start.java:326) [activetask.jar:?]

at com.softwareag.mft.activetask.Start.run(Start.java:215) [activetask.jar:?]

at com.softwareag.mft.activetask.Start.run(Start.java:94) [activetask.jar:?]

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_252]

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_252]

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_252]

at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_252]

at com.softwareag.mft.handlers.Common.runPlugin(Common.java:4125) [com.softwareag.mft.server_10.5.0.0007-0795.jar:?]

at com.softwareag.mft.server.Events6.doEventPlugin(Events6.java:988) [com.softwareag.mft.server_10.5.0.0007-0795.jar:?]

at com.softwareag.mft.server.services.impl.EventsAdmin.executeSchedule(EventsAdmin.java:404) [com.softwareag.mft.server_10.5.0.0007-0795.jar:?]

at com.softwareag.mft.proxy.EventsProxy.executeSchedule(EventsProxy.java:85) [com.softwareag.mft.proxy_10.5.0.0007-0795.jar:?]

at wm.mft.schedule.executeEvent(schedule.java:101) [?:?]

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_252]

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_252]

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_252]

at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_252]

at com.wm.app.b2b.server.JavaService.baseInvoke(JavaService.java:411) [wm-isserver.jar:10.5.0.0000-0084]

at com.wm.app.b2b.server.invoke.InvokeManager.process(InvokeManager.java:744) [wm-isserver.jar:10.5.0.0000-0084]

at com.wm.app.b2b.server.util.tspace.ReservationProcessor.process(ReservationProcessor.java:46) [wm-isserver.jar:10.5.0.0000-0084]

at com.wm.app.b2b.server.invoke.StatisticsProcessor.process(StatisticsProcessor.java:61) [wm-isserver.jar:10.5.0.0000-0084]

at com.wm.app.b2b.server.invoke.ServiceCompletionImpl.process(ServiceCompletionImpl.java:250) [wm-isserver.jar:10.5.0.0000-0084]

at com.wm.app.b2b.server.invoke.ValidateProcessor.process(ValidateProcessor.java:56) [wm-isserver.jar:10.5.0.0000-0084]

at com.wm.app.b2b.server.invoke.PipelineProcessor.process(PipelineProcessor.java:178) [wm-isserver.jar:10.5.0.0000-0084]

at com.wm.app.b2b.server.ACLManager.process(ACLManager.java:334) [wm-isserver.jar:10.5.0.0000-0084]

at com.wm.app.b2b.server.invoke.DispatchProcessor.process(DispatchProcessor.java:41) [wm-isserver.jar:10.5.0.0000-0084]

at com.wm.app.b2b.server.AuditLogManager.process(AuditLogManager.java:401) [wm-isserver.jar:10.5.0.0000-0084]

at com.wm.app.b2b.server.invoke.InvokeManager.invoke(InvokeManager.java:615) [wm-isserver.jar:10.5.0.0000-0084]

at com.wm.app.b2b.server.invoke.InvokeManager.invoke(InvokeManager.java:425) [wm-isserver.jar:10.5.0.0000-0084]

at com.wm.app.b2b.server.invoke.InvokeManager.invoke(InvokeManager.java:383) [wm-isserver.jar:10.5.0.0000-0084]

at com.wm.app.b2b.server.ServiceManager.invoke(ServiceManager.java:253) [wm-isserver.jar:10.5.0.0000-0084]

at com.wm.app.b2b.server.comm.DefaultServerRequestHandler.handleMessage(DefaultServerRequestHandler.java:127) [wm-isserver.jar:10.5.0.0000-0084]

at com.wm.app.b2b.server.HTTPMessageHandler.process(HTTPMessageHandler.java:163) [wm-isserver.jar:10.5.0.0000-0084]

at com.wm.app.b2b.server.HTTPDispatch.handleRequest(HTTPDispatch.java:223) [wm-isserver.jar:10.5.0.0000-0084]

at com.wm.app.b2b.server.Dispatch.run(Dispatch.java:430) [wm-isserver.jar:10.5.0.0000-0084]

at com.wm.util.pool.PooledThread.run(PooledThread.java:134) [wm-isclient.jar:1.0.3]

at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]

2020-08-31 08:56:46,413 TRACE [com.softwareag.mft.external.session ][6956] - [EVENTLOGID:5cceg700eh2jl06i0000003m:Copy to FosterVision]Closing the client due to exception. url:/

2020-08-31 08:56:46,413 TRACE [com.softwareag.mft.external.session ][6961] - [EVENTLOGID:5cceg700eh2jl06i0000003m]Logging out the client[240,114,291] url:/

2020-08-31 08:56:46,413 TRACE [com.softwareag.mft.external.session ][6962] - [EVENTLOGID:5cceg700eh2jl06i0000003m]Client logout successfully completed. [240,114,291] url:/

2020-08-31 08:56:46,413 TRACE [com.softwareag.mft.external.session ][6957] - [EVENTLOGID:5cceg700eh2jl06i0000003m:Copy to FosterVision]Removing 0 clients from pool.

2020-08-31 08:56:46,413 TRACE [com.softwareag.mft.external.session ][6956] - [EVENTLOGID:5cceg700eh2jl06i0000003m:Copy to FosterVision]Closing the client due to exception. url:FTPS://***:***@ftp.fostervision.net:990/

2020-08-31 08:56:46,413 TRACE [com.softwareag.mft.external.session ][6961] - [EVENTLOGID:5cceg700eh2jl06i0000003m]Logging out the client[377,937,077] url:FTPS://***:***@ftp.fostervision.net:990/

2020-08-31 08:56:46,413 INFO [com.softwareag.mft.external.session.ftp ][0023] - [5cceg700eh2jl06i0000003m:PRISM_SCCPD_SCCOE.Copy to FosterVision:0:377937077] Output stream:java.io.BufferedWriter@2a9cc24c, written:QUIT

2020-08-31 08:56:46,460 INFO [com.softwareag.mft.external.session.ftp ][0021] - [5cceg700eh2jl06i0000003m:PRISM_SCCPD_SCCOE.Copy to FosterVision:0:377937077] Input stream:java.io.BufferedReader@5a70092e, read:221 Goodbye

2020-08-31 08:56:46,460 TRACE [com.softwareag.mft.external.session ][6962] - [EVENTLOGID:5cceg700eh2jl06i0000003m]Client logout successfully completed. [377,937,077] url:FTPS://***:***@ftp.fostervision.net:990/

2020-08-31 08:56:46,460 TRACE [com.softwareag.mft.external.session ][6957] - [EVENTLOGID:5cceg700eh2jl06i0000003m:Copy to FosterVision]Removing 0 clients from pool.

2020-08-31 08:56:46,460 DEBUG [com.softwareag.mft.event ][1131] - [5cceg700eh2jl06i0000003m:PRISM_SCCPD_SCCOE.Copy to FosterVision:0] Error executing Copy to FosterVision. Error null

com.softwareag.mft.common.exception.MFTException: Error executing Copy to FosterVision. Error null

MAT_10.5_MWS_Fix7

MAT_10.5_Server_Fix7