ExecuteCommand tries to open new connection that times out
Hi,
I try to implement some basic integration: open connection, copy files to remote host, execute command, retrieve result files.
Opening a session and transferring files works fine but when I call even trivial
the library tries to open a new connection what finally times out.
What is wrong? (doing the same procedure from PuTTY works just fine).
Thanks Jan
the code:
The session output:
the WinSCP log:
I try to implement some basic integration: open connection, copy files to remote host, execute command, retrieve result files.
Opening a session and transferring files works fine but when I call even trivial
sesion.ExecuteCommand("echo HELLO");
What is wrong? (doing the same procedure from PuTTY works just fine).
Thanks Jan
the code:
using (Session session = new Session()) { try { // Connect session.Open(this.sessionOptions); session.DebugLogPath = @"C:\TEMP\remote_test_execution\WinSCP.log"; session.ExecuteCommand("echo HELLO").Check(); } catch { this.LogOutoutOfFailedSession(session); throw; } finally { session.RemoveFiles(remoteOutputFileName); session.RemoveFiles(remoteLogFileName); } }
The session output:
winscp> option batch on batch on reconnecttime 120 winscp> option confirm off confirm off winscp> option reconnecttime 120 reconnecttime 120 winscp> open "sftp://komix%5Cvrana:***@localhost" -hostkey="ssh-rsa 3072 oJdqIecUBpIDrb+ctARaHQsgR0RRW2bHsiGqTX4f4vw" -timeout=15 Searching for host... Connecting to host... Authenticating... Using username "komix\vrana". Authenticating with pre-entered password. Authenticated. Starting the session... Session started. Active session: [1] komix\vrana@localhost winscp> pwd /C:/Users/vrana winscp> call echo HELLO Searching for host... Connecting to host... Authenticating... Using username "komix\vrana". Authenticating with pre-entered password. Authenticated. Starting the session... Host is not communicating for more than 15 seconds. Still waiting... Note: If the problem repeats, try turning off 'Optimize connection buffer size'. Warning: Aborting this operation will close connection! (A)bort (60 s): Abort Terminated by user. Error skipping startup message. Your shell is probably incompatible with the application (BASH is recommended). winscp> exit
the WinSCP log:
[2021-10-07 15:52:25.489] [000d] .NET Framework build [2021-10-07 15:52:25.489] [000d] Executing assembly: WinSCPnet, Version=1.8.3.11614, Culture=neutral, PublicKeyToken=2271ec4a3c56d0bf [2021-10-07 15:52:25.489] [000d] Executing assembly codebase: file:///D:/Projects/ERIAN/local/Develop/GIT/FinalDebug/WinSCPnet.DLL [2021-10-07 15:52:25.489] [000d] Executing assembly location: D:\Projects\ERIAN\local\Develop\GIT\FinalDebug\WinSCPnet.dll [2021-10-07 15:52:25.489] [000d] Entry Assembly: unmanaged [2021-10-07 15:52:25.489] [000d] Operating system: Microsoft Windows NT 6.3.9600.0 [2021-10-07 15:52:25.489] [000d] Timezone: +02:00; Střední Evropa (letní čas) [2021-10-07 15:52:25.490] [000d] User: VRANA@KOMIX@VRANA; Interactive: True [2021-10-07 15:52:25.490] [000d] Runtime: 4.0.30319.42000 [2021-10-07 15:52:25.490] [000d] Console encoding: Input: Středoevropské jazyky (Windows) (1250); Output: Středoevropské jazyky (Windows) (1250) [2021-10-07 15:52:25.490] [000d] Working directory: D:\Projects\ERIAN\local\Develop\GIT\Support\Solutions\TestResults\VRANA_VRANA 2021-10-07 15_51_48\Out [2021-10-07 15:52:25.491] [000d] Assembly path: D:\Projects\ERIAN\local\Develop\GIT\FinalDebug\WinSCPnet.DLL [2021-10-07 15:52:25.491] [000d] Assembly product version: 5.19.2.0 [2021-10-07 15:52:53.262] [000d] Session.CreateCallstackAndLock entering [2021-10-07 15:52:53.263] [000d] Command: [call echo HELLO] [2021-10-07 15:52:53.263] [000d] ExeSessionProcess.ExecuteCommand entering [2021-10-07 15:52:53.264] [0006] Scheduling output: [winscp> call echo HELLO] [2021-10-07 15:52:53.265] [0006] ExeSessionProcess.ProcessEvent entering [2021-10-07 15:52:53.265] [0006] Scheduling output: [Searching for host...] [2021-10-07 15:52:53.265] [000d] ExeSessionProcess.ExecuteCommand leaving [2021-10-07 15:52:53.265] [0006] ExeSessionProcess.ProcessEvent leaving [2021-10-07 15:52:53.265] [000d] SessionLogReader.Read entering [2021-10-07 15:52:53.265] [000d] Read node 20: Whitespace [2021-10-07 15:52:53.266] [000d] Log contents: <?xml version="1.0" encoding="UTF-8"?> <session xmlns="http://winscp.net/schema/session/1.0" name="komix\vrana@localhost" start="2021-10-07T13:52:24.545Z"> <group name="open sftp://komix%5Cvrana:***@localhost -hostkey="ssh-rsa 3072 oJdqIecUBpIDrb+ctARaHQsgR0RRW2bHsiGqTX4f4vw" -timeout=15" start="2021-10-07T13:52:25.105Z"> </group> <group name="pwd" start="2021-10-07T13:52:25.408Z"> <cwd> <cwd value="/C:/Users/vrana" /> <result success="true" /> </cwd> </group> <group name="call echo HELLO" start="2021-10-07T13:52:53.264Z"> [2021-10-07 15:52:53.266] [000d] SessionLogReader.Read leaving [2021-10-07 15:52:53.266] [000d] SessionLogReader.Read entering [2021-10-07 15:52:53.266] [000d] Read node 21: Element group [2021-10-07 15:52:53.266] [000d] Log contents has not changed [2021-10-07 15:52:53.266] [000d] SessionLogReader.Read leaving [2021-10-07 15:52:53.266] [000d] SessionLogReader.Read entering [2021-10-07 15:52:53.266] [000d] Waiting for log update and dispatching events for 50 [2021-10-07 15:52:53.267] [000d] Output: [winscp> call echo HELLO] [2021-10-07 15:52:53.267] [000d] Output: [Searching for host...] [2021-10-07 15:52:53.268] [0006] ExeSessionProcess.ProcessEvent entering [2021-10-07 15:52:53.268] [0006] Scheduling output: [Connecting to host...] [2021-10-07 15:52:53.268] [0006] ExeSessionProcess.ProcessEvent leaving [2021-10-07 15:52:53.269] [000d] Output: [Connecting to host...] [2021-10-07 15:52:53.334] [000d] Waiting for log update and dispatching events for 100 [2021-10-07 15:52:53.442] [000d] Waiting for log update and dispatching events for 200 [2021-10-07 15:52:53.506] [0006] ExeSessionProcess.ProcessEvent entering [2021-10-07 15:52:53.506] [0006] Scheduling output: [Authenticating...] [2021-10-07 15:52:53.506] [0006] ExeSessionProcess.ProcessEvent leaving [2021-10-07 15:52:53.506] [000d] Output: [Authenticating...] [2021-10-07 15:52:53.507] [0006] ExeSessionProcess.ProcessEvent entering [2021-10-07 15:52:53.507] [0006] Scheduling output: [Using username "komix\vrana".] [2021-10-07 15:52:53.507] [0006] ExeSessionProcess.ProcessEvent leaving [2021-10-07 15:52:53.508] [000d] Output: [Using username "komix\vrana".] [2021-10-07 15:52:53.579] [0006] ExeSessionProcess.ProcessEvent entering [2021-10-07 15:52:53.579] [0006] Scheduling output: [Authenticating with pre-entered password.] [2021-10-07 15:52:53.579] [0006] ExeSessionProcess.ProcessEvent leaving [2021-10-07 15:52:53.580] [000d] Output: [Authenticating with pre-entered password.] [2021-10-07 15:52:53.656] [000d] Waiting for log update and dispatching events for 400 [2021-10-07 15:52:53.717] [0006] ExeSessionProcess.ProcessEvent entering [2021-10-07 15:52:53.717] [0006] Scheduling output: [Authenticated.] [2021-10-07 15:52:53.717] [0006] ExeSessionProcess.ProcessEvent leaving [2021-10-07 15:52:53.718] [000d] Output: [Authenticated.] [2021-10-07 15:52:53.718] [0006] ExeSessionProcess.ProcessEvent entering [2021-10-07 15:52:53.718] [0006] Scheduling output: [Starting the session...] [2021-10-07 15:52:53.718] [0006] ExeSessionProcess.ProcessEvent leaving [2021-10-07 15:52:53.719] [000d] Output: [Starting the session...] [2021-10-07 15:52:54.072] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:52:54.881] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:52:55.690] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:52:56.512] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:52:57.327] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:52:58.142] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:52:58.947] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:52:59.755] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:00.577] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:01.378] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:02.203] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:03.019] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:03.838] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:04.643] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:05.465] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:06.282] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:07.092] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:07.899] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:08.713] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:09.533] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:10.075] [0006] ExeSessionProcess.ProcessEvent entering [2021-10-07 15:53:10.075] [0006] Scheduling output: [Host is not communicating for more than 15 seconds.] [2021-10-07 15:53:10.075] [0006] Scheduling output: [Still waiting...] [2021-10-07 15:53:10.075] [0006] Scheduling output: [Note: If the problem repeats, try turning off 'Optimize connection buffer size'.] [2021-10-07 15:53:10.076] [0006] Scheduling output: [Warning: Aborting this operation will close connection!] [2021-10-07 15:53:10.076] [0006] ExeSessionProcess.ProcessEvent leaving [2021-10-07 15:53:10.076] [000d] Output: [Host is not communicating for more than 15 seconds.] [2021-10-07 15:53:10.076] [000d] Output: [Still waiting...] [2021-10-07 15:53:10.076] [000d] Output: [Note: If the problem repeats, try turning off 'Optimize connection buffer size'.] [2021-10-07 15:53:10.076] [000d] Output: [Warning: Aborting this operation will close connection!] [2021-10-07 15:53:10.077] [0006] ExeSessionProcess.ProcessEvent entering [2021-10-07 15:53:10.078] [0006] ExeSessionProcess.ProcessEvent leaving [2021-10-07 15:53:10.341] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:11.152] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:11.958] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:12.768] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:13.593] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:14.402] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:15.215] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:16.027] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:16.837] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:17.649] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:18.466] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:19.280] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:20.092] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:20.901] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:21.708] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:22.529] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:23.338] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:24.145] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:24.956] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:25.779] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:26.590] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:27.397] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:28.220] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:29.030] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:29.840] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:30.653] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:31.460] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:32.280] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:33.089] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:33.899] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:34.710] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:35.523] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:36.334] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:37.147] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:37.957] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:38.774] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:39.585] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:40.401] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:41.209] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:42.030] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:42.839] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:43.651] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:44.463] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:45.271] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:46.084] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:46.902] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:47.717] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:48.528] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:49.334] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:50.147] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:50.967] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:51.774] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:52.583] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:53.405] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:54.218] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:55.027] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:55.836] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:56.650] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:57.462] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:58.271] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:59.096] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:53:59.901] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:54:00.713] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:54:01.524] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:54:02.338] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:54:03.152] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:54:03.966] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:54:04.783] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:54:05.593] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:54:06.403] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:54:07.212] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:54:08.032] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:54:08.839] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:54:09.649] [000d] Waiting for log update and dispatching events for 800 [2021-10-07 15:54:10.458] [000d] Timeout waiting for WinSCP to respond - asking for callstack [2021-10-07 15:54:10.459] [000d] ExeSessionProcess.RequestCallstack entering [2021-10-07 15:54:10.459] [000d] Setting event WinSCPCallstack21520 [2021-10-07 15:54:10.521] [000d] Callstack file D:\tmp\_tmp\WinSCPCallstack21520.txt has been created [2021-10-07 15:54:10.633] [000d] (00071D1C) ntdll.dll.ZwDelayExecution (001239CA) KERNELBASE.dll.Sleep (0005F8DB) (0011DC36) KERNELBASE.dll.LoadStringBaseExW (00FAFE97) (00FB0838) (00FB1276) (00FAB020) (00FC029C) (003775C1) (00FC03C1) (00FC09D8) (00FC0105) (00FC0136) (003775B2) (00438A80) (00D742BD) (003775C1) (00FC03C1) (00438A9C) (0043B88C) (003775C1) (00FC03C1) (00D7428F) (00F961AD) (003775B2) (00DBECCD) (0043C9F3) (00FC03C1) (00438A9C) (0043B88C) (003775C1) (00FC03C1) (00C742C4) (00D32587) (00D34902) (00FAA4C3) (00D31D32) (00C861E9) (00438ABD) (00FBF14E) (00D31F7E) (00D31FB0) (00D11232) (00D32E50) (003775C1) (00FC03C1) (00D117B4) (00D11863) (00438A9C) (0043B88C) (003775C1) (00D11D74) (00DC0274) (00D11A55) (003775C1) (00FC03C1) (00DC491A) (00DC4949) (00FC03C1) (00DBABCC) (0043A458) (0043A746) (0043A797) (00439B88) (003ABE1C) (0000308C) (0043A4C8) (00439C23) (00438A9C) (00439A98) (00D3CD5B) (00FC03C1) (00DCD4CE) (00D21B8E) (00D22876) (00FC03C1) (00D22C95) (00D22CAD) (00D1DF61) @@Scpfilesystem@Finalize (00D1EF89) (00407C83) (00407CAE) (00CCD69C) (00D7E700) (00407CAE) (00CCD69C) (00D74583) (00DDD60E) (00D2C35E) (00065288) (00C8E3F8) (00D204F7) (0005B75B) (0005B37F) (00064A1F) (003775B2) (00FC0233) (00CE280F) (00438A9C) (0043B88C) (003775C1) (00FC03C1) (000C51C6) (0006D1CA) (003775C1) (00FC03C1) (00438A9C) (0043B88C) (00106F51) (003775C1) (00242BF5) (002433DA) (00FAA61A) (0004B7B7) ntdll.dll.RtlDeactivateActivationContextUnsafeFast (00FAA4C3) (003C79D8) (000426D9) USER32.dll (00039665) USER32.dll (000398A9) USER32.dll (000396A7) USER32.dll (00039478) USER32.dll (000398A9) USER32.dll (00002650) (00002658) (00FBA625) (0001EA27) KERNEL32.DLL.BaseThreadInitThunk (00066A9C) ntdll.dll.RtlGetAppContainerNamedObjectPath (00066A69) ntdll.dll.RtlGetAppContainerNamedObjectPath [2021-10-07 15:54:10.633] [000d] ExeSessionProcess.RequestCallstack leaving [2021-10-07 15:54:10.633] [000d] Session.Cleanup entering [2021-10-07 15:54:10.633] [000d] Terminating process [2021-10-07 15:54:10.633] [000d] Command: [exit] [2021-10-07 15:54:10.633] [000d] ExeSessionProcess.ExecuteCommand entering [2021-10-07 15:54:10.633] [000d] ExeSessionProcess.ExecuteCommand leaving [2021-10-07 15:54:10.633] [000d] ExeSessionProcess.Close entering [2021-10-07 15:54:10.633] [000d] Waiting for process to exit (2000 ms) [2021-10-07 15:54:10.757] [0006] ExeSessionProcess.ProcessEvent entering [2021-10-07 15:54:10.757] [0006] Scheduling output: [(A)bort (60 s): Abort] [2021-10-07 15:54:10.757] [0006] ExeSessionProcess.ProcessEvent leaving [2021-10-07 15:54:10.765] [0006] ExeSessionProcess.ProcessEvent entering [2021-10-07 15:54:10.765] [0006] Scheduling output: [Terminated by user.] [2021-10-07 15:54:10.765] [0006] Scheduling output: [Error skipping startup message. Your shell is probably incompatible with the application (BASH is recommended).] [2021-10-07 15:54:10.765] [0006] ExeSessionProcess.ProcessEvent leaving [2021-10-07 15:54:10.765] [0006] ExeSessionProcess.ProcessEvent entering [2021-10-07 15:54:10.765] [0006] ExeSessionProcess.ProcessTitleEvent entering [2021-10-07 15:54:10.765] [0006] Not-supported title event [komix\vrana@localhost - WinSCP] [2021-10-07 15:54:10.765] [0006] ExeSessionProcess.ProcessTitleEvent leaving [2021-10-07 15:54:10.766] [0006] ExeSessionProcess.ProcessEvent leaving [2021-10-07 15:54:10.766] [0006] ExeSessionProcess.ProcessEvent entering [2021-10-07 15:54:10.766] [0006] ExeSessionProcess.ProcessEvent leaving [2021-10-07 15:54:10.767] [0006] ExeSessionProcess.ProcessEvent entering [2021-10-07 15:54:10.767] [0006] ExeSessionProcess.ProcessInputEvent entering [2021-10-07 15:54:10.768] [0006] Scheduling output: [winscp> exit] [2021-10-07 15:54:10.768] [0006] ExeSessionProcess.ProcessInputEvent leaving [2021-10-07 15:54:10.768] [0006] ExeSessionProcess.ProcessEvent leaving [2021-10-07 15:54:10.818] [000d] ExeSessionProcess.Close leaving [2021-10-07 15:54:10.818] [000d] ExeSessionProcess.Dispose entering [2021-10-07 15:54:10.881] [0006] Aborted [2021-10-07 15:54:10.890] [000d] Closing job [2021-10-07 15:54:10.890] [000d] ExeSessionProcess.Dispose leaving [2021-10-07 15:54:10.890] [000d] Disposing log readers [2021-10-07 15:54:10.890] [000d] SessionElementLogReader.Dispose entering [2021-10-07 15:54:10.890] [000d] ElementLogReader.Dispose(session@0) entering [2021-10-07 15:54:10.890] [000d] ElementLogReader.ReadToEnd(session@0) entering [2021-10-07 15:54:10.890] [000d] SessionLogReader.Read entering [2021-10-07 15:54:10.890] [000d] Not reading, session has timed out [2021-10-07 15:54:10.890] [000d] SessionLogReader.Read leaving [2021-10-07 15:54:10.890] [000d] ElementLogReader.ReadToEnd(session@0) leaving [2021-10-07 15:54:10.890] [000d] ElementLogReader.Dispose(session@0) leaving [2021-10-07 15:54:10.890] [000d] SessionElementLogReader.Dispose leaving [2021-10-07 15:54:10.891] [000d] SessionLogReader.Dispose entering [2021-10-07 15:54:10.891] [000d] Log contents: <?xml version="1.0" encoding="UTF-8"?> <session xmlns="http://winscp.net/schema/session/1.0" name="komix\vrana@localhost" start="2021-10-07T13:52:24.545Z"> <group name="open sftp://komix%5Cvrana:***@localhost -hostkey="ssh-rsa 3072 oJdqIecUBpIDrb+ctARaHQsgR0RRW2bHsiGqTX4f4vw" -timeout=15" start="2021-10-07T13:52:25.105Z"> </group> <group name="pwd" start="2021-10-07T13:52:25.408Z"> <cwd> <cwd value="/C:/Users/vrana" /> <result success="true" /> </cwd> </group> <group name="call echo HELLO" start="2021-10-07T13:52:53.264Z"> <call> <command value="echo HELLO" /> <destination value="/C:/Users/vrana" /> <result success="false"> <message>Terminated by user.</message> <message>Error skipping startup message. Your shell is probably incompatible with the application (BASH is recommended).</message> </result> </call> <failure> <message>Terminated by user.</message> <message>Error skipping startup message. Your shell is probably incompatible with the application (BASH is recommended).</message> </failure> </group> <group name="exit" start="2021-10-07T13:54:10.768Z"> </group> </session> [2021-10-07 15:54:10.891] [000d] Closing log [2021-10-07 15:54:10.891] [000d] SessionLogReader.Dispose leaving [2021-10-07 15:54:10.891] [000d] Deleting XML log file [D:\tmp\_tmp\wscp14DC.03FA645B.tmp] [2021-10-07 15:54:10.891] [000d] Session.Cleanup leaving [2021-10-07 15:54:10.891] [000d] Exception: System.TimeoutException: Timeout waiting for WinSCP to respond [2021-10-07 15:54:10.953] [000d] SessionLogReader.Read leaving [2021-10-07 15:54:10.953] [000d] ElementLogReader.Dispose(group@1) entering [2021-10-07 15:54:10.953] [000d] ElementLogReader.ReadToEnd(group@1) entering [2021-10-07 15:54:10.954] [000d] SessionLogReader.Read entering [2021-10-07 15:54:10.954] [000d] Not reading, session has timed out [2021-10-07 15:54:10.954] [000d] SessionLogReader.Read leaving [2021-10-07 15:54:10.954] [000d] ElementLogReader.ReadToEnd(group@1) leaving [2021-10-07 15:54:10.954] [000d] ElementLogReader.Dispose(group@1) leaving [2021-10-07 15:54:10.954] [000d] Session.CreateCallstackAndLock leaving [2021-10-07 15:54:56.000] [000d] Session.CreateCallstackAndLock entering [2021-10-07 15:54:56.001] [000d] Session.DoRemoveFiles entering [2021-10-07 15:54:56.001] [000d] Exception: System.InvalidOperationException: Session is not opened [2021-10-07 15:54:56.036] [000d] Session.DoRemoveFiles leaving [2021-10-07 15:54:56.036] [000d] Session.CreateCallstackAndLock leaving [2021-10-07 15:54:56.037] [000d] Session.CreateCallstackAndLock entering [2021-10-07 15:54:56.037] [000d] Session.Cleanup entering [2021-10-07 15:54:56.037] [000d] Disposing log readers [2021-10-07 15:54:56.037] [000d] Session.Cleanup leaving
