Waiting for log update and dispatching events for 1000

Hello,

1) "Waiting for log update and dispatching events for 1000"
We use .NET SFTP to upload many 50 MB files.
The program uploads 10 GB then blocks with "Waiting for log update and dispatching events for 1000" message looping.
The only way we found is to kill process with CTRL+ALT+SUPP.

We need to use SFTP as batch :
WinSCP is part of a large program that do many things.
It will run every night to send many files and write data to database.

When WinSCP blocks, main program can not exit or do anything (go to the next step).
It's waiting WinSCP to respond but it never responds.
The main program freez and blocks next treatments.

What we need :
When somehing goes wrong it should raise an error and give back the hand to the main program.
So we could restart or reconnect and retry sending files (or exit SFTP loop and go next step).

2) There is an other problem
If the main program is run automaticly every night : after one week, many WinSCP processes are running on the server (and they do nothing : looping with the "Waiting for log update" message).
So we must kill main program, then kill every WinSCP process.
It would be cool if WinSCP process exit automaticly if the main program die.

Help Please !
------------------------------------------------------------------------------------------------------------------------
WinScp.dll :
File version : 1.0.2.2735
Product version : 5.1.1.0
------------------------------------------------------------------------------------------------------------------------
.NET functions used :
-Session.CreateDirectory
-Session.FileExists
-Session.GetFiles
-Session.ListDirectory
-Session.PutFiles
-Session.RemoveFiles
-Session.Open
------------------------------------------------------------------------------------------------------------------------
Options used :
TransferOptions.TransferMode = TransferMode.Binary
SessionsOptions.SshHostKeyFingerprint = Fingerprint
SessionsOptions.Protocol = Protocol.Sftp
Session.ExecutablePath = ExecutablePath
Session.SessionLogPath = SessionLogPath
Session.DebugLogPath = DebugLogPath
------------------------------------------------------------------------------------------------------------------------
Here is the session log last part :

. 2013-02-11 22:17:56.129 File: "\\Archivage\archivage\TRANSFERTVERSBNF\DEPOTS\CNACGP_GCOLL_150000000759703\4N62462.tif"
. 2013-02-11 22:17:56.144 Copying "\\Archivage\archivage\TRANSFERTVERSBNF\DEPOTS\CNACGP_GCOLL_150000000759703\4N62462.tif" to remote directory started.
. 2013-02-11 22:17:56.144 Binary transfer mode selected.
. 2013-02-11 22:17:56.144 Checking existence of file.
> 2013-02-11 22:17:56.144 Type: SSH_FXP_LSTAT, Size: 66, Number: 250080775
< 2013-02-11 22:17:56.144 Type: SSH_FXP_STATUS, Size: 31, Number: 250080775
< 2013-02-11 22:17:56.144 Status code: 2
. 2013-02-11 22:17:56.144 Checking existence of partially transfered file.
> 2013-02-11 22:17:56.144 Type: SSH_FXP_LSTAT, Size: 75, Number: 250081031
< 2013-02-11 22:17:56.160 Type: SSH_FXP_STATUS, Size: 31, Number: 250081031
< 2013-02-11 22:17:56.160 Status code: 2
. 2013-02-11 22:17:56.160 Opening remote file.
> 2013-02-11 22:17:56.160 Type: SSH_FXP_OPEN, Size: 91, Number: 250081283
< 2013-02-11 22:17:57.143 Type: SSH_FXP_HANDLE, Size: 10, Number: 250081283
> 2013-02-11 22:17:57.174 Type: SSH_FXP_WRITE, Size: 4118, Number: 250081798
. 2013-02-11 22:19:45.500 12281 skipped SSH_FXP_WRITE, SSH_FXP_READ, SSH_FXP_DATA and SSH_FXP_STATUS packets.
> 2013-02-11 22:19:45.500 Type: SSH_FXP_CLOSE, Size: 10, Number: 251654404
< 2013-02-11 22:19:45.500 Type: SSH_FXP_STATUS, Size: 26, Number: 251653382
< 2013-02-11 22:19:45.500 Status code: 0
< 2013-02-11 22:19:45.500 Type: SSH_FXP_STATUS, Size: 26, Number: 251653638
< 2013-02-11 22:19:45.516 Type: SSH_FXP_STATUS, Size: 26, Number: 251653894
< 2013-02-11 22:19:45.594 Type: SSH_FXP_STATUS, Size: 26, Number: 251654150
< 2013-02-11 22:19:45.953 Type: SSH_FXP_STATUS, Size: 26, Number: 251654404
< 2013-02-11 22:19:45.953 Status code: 0
> 2013-02-11 22:19:45.953 Type: SSH_FXP_RENAME, Size: 136, Number: 251654674
< 2013-02-11 22:19:46.015 Type: SSH_FXP_STATUS, Size: 26, Number: 251654674
< 2013-02-11 22:19:46.031 Status code: 0
> 2013-02-11 22:19:46.031 Type: SSH_FXP_SETSTAT, Size: 78, Number: 250081545
< 2013-02-11 22:19:46.062 Type: SSH_FXP_STATUS, Size: 26, Number: 250081545
< 2013-02-11 22:19:46.062 Status code: 0
> 2013-02-11 22:19:46.530 Script: stat -- "/versement/depot/CNACGP_GCOLL_150000000759703/4N62462.tif.md5"
. 2013-02-11 22:19:46.530 Listing file "/versement/depot/CNACGP_GCOLL_150000000759703/4N62462.tif.md5".
> 2013-02-11 22:19:46.530 Type: SSH_FXP_LSTAT, Size: 70, Number: 251654919
< 2013-02-11 22:19:46.561 Type: SSH_FXP_STATUS, Size: 31, Number: 251654919
< 2013-02-11 22:19:46.561 Status code: 2, Message: 251654919, Server: No such file, Language: en
------------------------------------------------------------------------------------------------------------------------

Here is the debug log last part :

[2013-02-11 22:19:46.530Z] [0001] Command: [stat -- "/versement/depot/CNACGP_GCOLL_150000000759703/4N62462.tif.md5"]
[2013-02-11 22:19:46.530Z] [0001] ExeSessionProcess.ExecuteCommand entering
[2013-02-11 22:19:46.530Z] [0001] ExeSessionProcess.ExecuteCommand leaving
[2013-02-11 22:19:46.530Z] [0001] SessionLogReader.Read entering
[2013-02-11 22:19:46.530Z] [0001] Error logging log contents
[2013-02-11 22:19:46.530Z] [0001] SessionLogReader.Read leaving
[2013-02-11 22:19:46.530Z] [0001] SessionLogReader.Read entering
[2013-02-11 22:19:46.530Z] [0001] Waiting for log update and dispatching events for 125
[2013-02-11 22:19:46.530Z] [0003] Scheduling output: [winscp> stat -- "/versement/depot/CNACGP_GCOLL_150000000759703/4N62462.tif.md5"]
[2013-02-11 22:19:46.530Z] [0003] ExeSessionProcess.ProcessInputEvent leaving
[2013-02-11 22:19:46.530Z] [0003] ExeSessionProcess.ProcessEvent leaving
[2013-02-11 22:19:46.530Z] [0001] Output: [winscp> stat -- "/versement/depot/CNACGP_GCOLL_150000000759703/4N62462.tif.md5"]
[2013-02-11 22:19:46.670Z] [0001] Opening log
[2013-02-11 22:19:46.670Z] [0001] Log opened with write sharing
[2013-02-11 22:19:46.670Z] [0001] Skipping 60780 elements
[2013-02-11 22:19:46.686Z] [0001] Error logging log contents
[2013-02-11 22:19:46.686Z] [0001] SessionLogReader.Read leaving
[2013-02-11 22:19:46.686Z] [0001] SessionLogReader.Read entering
[2013-02-11 22:19:46.686Z] [0001] Error logging log contents
[2013-02-11 22:19:46.686Z] [0001] SessionLogReader.Read leaving
[2013-02-11 22:19:46.686Z] [0001] SessionLogReader.Read entering
[2013-02-11 22:19:46.686Z] [0001] Error logging log contents
[2013-02-11 22:19:46.686Z] [0001] SessionLogReader.Read leaving
[2013-02-11 22:19:46.686Z] [0001] SessionLogReader.Read entering
[2013-02-11 22:19:46.702Z] [0001] Error logging log contents
[2013-02-11 22:19:46.702Z] [0001] SessionLogReader.Read leaving
[2013-02-11 22:19:46.702Z] [0001] SessionLogReader.Read entering
[2013-02-11 22:19:46.702Z] [0001] Error logging log contents
[2013-02-11 22:19:46.702Z] [0001] SessionLogReader.Read leaving
[2013-02-11 22:19:46.702Z] [0001] SessionLogReader.Read entering
[2013-02-11 22:19:46.702Z] [0001] Error logging log contents
[2013-02-11 22:19:46.702Z] [0001] SessionLogReader.Read leaving
[2013-02-11 22:19:46.702Z] [0001] SessionLogReader.Read entering
[2013-02-11 22:19:46.702Z] [0001] Error logging log contents
[2013-02-11 22:19:46.702Z] [0001] SessionLogReader.Read leaving
[2013-02-11 22:19:46.702Z] [0001] SessionLogReader.Read entering
[2013-02-11 22:19:46.702Z] [0001] Error logging log contents
[2013-02-11 22:19:46.702Z] [0001] SessionLogReader.Read leaving
[2013-02-11 22:19:46.702Z] [0001] SessionLogReader.Read entering
[2013-02-11 22:19:46.702Z] [0001] Error logging log contents
[2013-02-11 22:19:46.702Z] [0001] SessionLogReader.Read leaving
[2013-02-11 22:19:46.702Z] [0001] SessionLogReader.Read entering
[2013-02-11 22:19:46.702Z] [0001] Error logging log contents
[2013-02-11 22:19:46.702Z] [0001] SessionLogReader.Read leaving
[2013-02-11 22:19:46.702Z] [0001] SessionLogReader.Read entering
[2013-02-11 22:19:46.702Z] [0001] Error logging log contents
[2013-02-11 22:19:46.702Z] [0001] SessionLogReader.Read leaving
[2013-02-11 22:19:46.702Z] [0001] SessionLogReader.Read entering
[2013-02-11 22:19:46.702Z] [0001] Error logging log contents
[2013-02-11 22:19:46.717Z] [0001] SessionLogReader.Read leaving
[2013-02-11 22:19:46.717Z] [0001] SessionLogReader.Read entering
[2013-02-11 22:19:46.717Z] [0001] Error logging log contents
[2013-02-11 22:19:46.717Z] [0001] SessionLogReader.Read leaving
[2013-02-11 22:19:46.717Z] [0001] SessionLogReader.Read entering
[2013-02-11 22:19:46.717Z] [0001] Error logging log contents
[2013-02-11 22:19:46.717Z] [0001] SessionLogReader.Read leaving
[2013-02-11 22:19:46.717Z] [0001] SessionLogReader.Read entering
[2013-02-11 22:19:46.717Z] [0001] Error logging log contents
[2013-02-11 22:19:46.717Z] [0001] SessionLogReader.Read leaving
[2013-02-11 22:19:46.717Z] [0001] SessionLogReader.Read entering
[2013-02-11 22:19:46.717Z] [0001] Error logging log contents
[2013-02-11 22:19:46.717Z] [0001] SessionLogReader.Read leaving
[2013-02-11 22:19:46.717Z] [0001] SessionLogReader.Read entering
[2013-02-11 22:19:46.717Z] [0001] Error logging log contents
[2013-02-11 22:19:46.717Z] [0001] SessionLogReader.Read leaving
[2013-02-11 22:19:46.717Z] [0001] SessionLogReader.Read entering
[2013-02-11 22:19:46.717Z] [0001] Error logging log contents
[2013-02-11 22:19:46.717Z] [0001] SessionLogReader.Read leaving
[2013-02-11 22:19:46.717Z] [0001] SessionLogReader.Read entering
[2013-02-11 22:19:46.717Z] [0001] Error logging log contents
[2013-02-11 22:19:46.717Z] [0001] SessionLogReader.Read leaving
[2013-02-11 22:19:46.717Z] [0001] ElementLogReader.ReadToEnd entering
[2013-02-11 22:19:46.717Z] [0001] SessionLogReader.Read entering
[2013-02-11 22:19:46.717Z] [0001] Error logging log contents
[2013-02-11 22:19:46.717Z] [0001] SessionLogReader.Read leaving
[2013-02-11 22:19:46.717Z] [0001] SessionLogReader.Read entering
[2013-02-11 22:19:46.717Z] [0001] Waiting for log update and dispatching events for 125
[2013-02-11 22:19:46.873Z] [0001] Opening log
[2013-02-11 22:19:46.936Z] [0001] Log opened with write sharing
[2013-02-11 22:19:46.936Z] [0001] Skipping 60800 elements
[2013-02-11 22:19:46.951Z] [0001] Waiting for log update and dispatching events for 250
[2013-02-11 22:19:47.216Z] [0001] Opening log
[2013-02-11 22:19:47.216Z] [0001] Log opened with write sharing
[2013-02-11 22:19:47.216Z] [0001] Skipping 60800 elements
[2013-02-11 22:19:47.232Z] [0001] Waiting for log update and dispatching events for 500
[2013-02-11 22:19:47.747Z] [0001] Opening log
[2013-02-11 22:19:47.747Z] [0001] Log opened with write sharing
[2013-02-11 22:19:47.747Z] [0001] Skipping 60800 elements
[2013-02-11 22:19:47.762Z] [0001] Waiting for log update and dispatching events for 1000
[2013-02-11 22:19:48.776Z] [0001] Opening log
[2013-02-11 22:19:48.776Z] [0001] Log opened with write sharing
[2013-02-11 22:19:48.776Z] [0001] Skipping 60800 elements
[2013-02-11 22:19:48.792Z] [0001] Waiting for log update and dispatching events for 1000
[2013-02-11 22:19:49.806Z] [0001] Opening log
[2013-02-11 22:19:49.806Z] [0001] Log opened with write sharing
[2013-02-11 22:19:49.806Z] [0001] Skipping 60800 elements
....
[2013-02-12 09:53:24.782Z] [0001] Opening log
[2013-02-12 09:53:24.783Z] [0001] Log opened with write sharing
[2013-02-12 09:53:24.784Z] [0001] Skipping 60800 elements
[2013-02-12 09:53:24.804Z] [0001] Waiting for log update and dispatching events for 1000

Can you please email me debug log using the 5.1.3?

martin wrote:

Can you please email me debug log using the 5.1.3?

Hello, i'm testing 5.1.3 version of the .NET api.
After sending 60 files (1.6 Go) the debug log is about 260 Mo.
This morning we sent 600 files (16 Gb) and the debug log is ~= 3.7 Gb.

So impossible to edit it with NotePad++ !
(and impossible to send it to you in the state : we must cut connexion and othe info before submit you the log)

Is there a way to reduce it ? Perhaps it logs too much things ?

An idea :
-do not log everyhing in one single file
-have an option to have multiple smaller debug log files
-have a compact debug log format : write tiny codes instead of full text events

Alexey

Hello Martin, i sent you logs.

Best regards,

Alexey