Debug log file grew to exceed disk space
I am running a single instance of a windows service using WinSCPnet.dll for SFTP transfer of approximately 20K files daily. These files arrive at the server in batches and are usually 90% arrived by 08:00.
I have debug logging enabled thus:
session.DebugLogPath = Path.GetDirectoryName([Assembly].GetExecutingAssembly().Location) + "\sftpGet.log"
This process has been working very reliably until this weekend when the debuglog (sftpGet.log) grew until the disk capacity (100 GByte) was exceeded. The log file was 84 GByte at this stage, so I hope that you will forgive me if I don't attach it. I have however included the head of this file below.
To clear the problem I stopped the service, moved the log file (I have retained it in case you have any suggestions about how to retrieve useful info from such a large file), got about 6000 files using WinSCP.exe, restarted the service, and everything has run as normal since then.
Is there a way to limit the size of the debuglog to prevent this problem from happening?
Thanks, Brian
[2014-08-22 02:25:56.215Z] [000f] Executing Assembly: WinSCPnet, Version=1.1.6.4433, Culture=neutral, PublicKeyToken=xxx; Path: C:\Program Files\WinSCPnet.DLL; Location: C:\Program Files\WinSCPnet.dll; Product: 5.5.4.0
[2014-08-22 02:25:56.215Z] [000f] Entry Assembly: AmbitSFTP, Version=1.7.16.1030, Culture=neutral, PublicKeyToken=null
[2014-08-22 02:25:56.215Z] [000f] Operating system: Microsoft Windows NT 6.2.9200.0
[2014-08-22 02:25:56.216Z] [000f] User: SYSTEM; Interactive: False
[2014-08-22 02:25:56.216Z] [000f] Runtime: 4.0.30319.34209
[2014-08-22 02:25:56.216Z] [000f] Console encoding: Input: Western European (Windows) (1252); Output: Western European (Windows) (1252)
[2014-08-22 02:25:56.216Z] [000f] Working directory: C:\Windows\system32
[2014-08-22 02:25:56.223Z] [000f] Session.ListDirectory entering
[2014-08-22 02:25:56.223Z] [000f] Command: [ls -- "/deliver/"]
[2014-08-22 02:25:56.223Z] [000f] ExeSessionProcess.ExecuteCommand entering
[2014-08-22 02:25:56.223Z] [000f] ExeSessionProcess.ExecuteCommand leaving
[2014-08-22 02:25:56.223Z] [0005] Scheduling output: [winscp> ls -- "/deliver/"]
[2014-08-22 02:25:56.223Z] [000f] SessionLogReader.Read entering
[2014-08-22 02:25:56.223Z] [000f] Read node 8: Whitespace
[2014-08-22 02:25:56.223Z] [000f] Log contents:
<?xml version="1.0" encoding="UTF-8"?>
<session xmlns="https://winscp.net/schema/session/1.0" name="xxx@999" start="2014-08-21T14:25:54.290Z">
<group name="open -hostkey="ssh-rsa 2048 9f:31:79:28:etc" -timeout=15 sftp://xxx:***@999" start="2014-08-21T14:25:55.862Z">
</group>
[2014-08-22 02:25:56.223Z] [000f] SessionLogReader.Read leaving
[2014-08-22 02:25:56.223Z] [000f] SessionLogReader.Read entering
[2014-08-22 02:25:56.223Z] [000f] Closing log
[2014-08-22 02:25:56.223Z] [000f] Error parsing session log file, but it is not closed yet, will retry
[2014-08-22 02:25:56.223Z] [000f] Waiting for log update and dispatching events for 125
[2014-08-22 02:25:56.223Z] [000f] Output: [winscp> ls -- "/deliver/"]
[2014-08-22 02:25:56.348Z] [000f] Opening log without write sharing
[2014-08-22 02:25:56.348Z] [000f] Opening log with write sharing
[2014-08-22 02:25:56.348Z] [000f] Log opened
[2014-08-22 02:25:56.348Z] [000f] Skipping 8 nodes
[2014-08-22 02:25:56.348Z] [000f] Read node 9: Element group
[2014-08-22 02:25:56.348Z] [000f] Log contents:
<?xml version="1.0" encoding="UTF-8"?>
<session xmlns="https://winscp.net/schema/session/1.0" name="xxx@999" start="2014-08-21T14:25:54.290Z">
<group name="open -hostkey="ssh-rsa 2048 9f:31:79:28:a7:etc" -timeout=15 sftp://xxx:***@999" start="2014-08-21T14:25:55.862Z">
</group>
<group name="ls -- "/deliver/"" start="2014-08-21T14:25:56.223Z">
[2014-08-22 02:25:56.348Z] [000f] SessionLogReader.Read leaving
[2014-08-22 02:25:56.348Z] [000f] SessionLogReader.Read entering
[2014-08-22 02:25:56.348Z] [000f] Read node 10: Whitespace
[2014-08-22 02:25:56.348Z] [000f] Log contents has not changed
[2014-08-22 02:25:56.348Z] [000f] SessionLogReader.Read leaving
[2014-08-22 02:25:56.348Z] [000f] SessionLogReader.Read entering
[2014-08-22 02:25:56.349Z] [000f] Closing log
[2014-08-22 02:25:56.349Z] [000f] Error parsing session log file, but it is not closed yet, will retry
[2014-08-22 02:25:56.349Z] [000f] Waiting for log update and dispatching events for 125
[2014-08-22 02:25:56.474Z] [000f] Opening log without write sharing
[2014-08-22 02:25:56.474Z] [000f] Opening log with write sharing
[2014-08-22 02:25:56.474Z] [000f] Log opened
[2014-08-22 02:25:56.474Z] [000f] Skipping 10 nodes
[2014-08-22 02:25:56.474Z] [000f] Closing log
[2014-08-22 02:25:56.474Z] [000f] Error parsing session log file, but it is not closed yet, will retry
[2014-08-22 02:25:56.474Z] [000f] Waiting for log update and dispatching events for 250
[2014-08-22 02:25:56.724Z] [000f] Opening log without write sharing
[2014-08-22 02:25:56.724Z] [000f] Opening log with write sharing
[2014-08-22 02:25:56.724Z] [000f] Log opened
[2014-08-22 02:25:56.724Z] [000f] Skipping 10 nodes
[2014-08-22 02:25:56.724Z] [000f] Closing log
[2014-08-22 02:25:56.724Z] [000f] Error parsing session log file, but it is not closed yet, will retry
[2014-08-22 02:25:56.724Z] [000f] Waiting for log update and dispatching events for 500
[2014-08-22 02:25:57.224Z] [000f] Opening log without write sharing
[2014-08-22 02:25:57.224Z] [000f] Opening log with write sharing
[2014-08-22 02:25:57.224Z] [000f] Log opened
[2014-08-22 02:25:57.224Z] [000f] Skipping 10 nodes
[2014-08-22 02:25:57.224Z] [000f] Closing log
[2014-08-22 02:25:57.224Z] [000f] Error parsing session log file, but it is not closed yet, will retry
[2014-08-22 02:25:57.224Z] [000f] Waiting for log update and dispatching events for 500
[2014-08-22 02:25:57.724Z] [000f] Opening log without write sharing
[2014-08-22 02:25:57.724Z] [000f] Opening log with write sharing
[2014-08-22 02:25:57.724Z] [000f] Log opened
[2014-08-22 02:25:57.724Z] [000f] Skipping 10 nodes
[2014-08-22 02:25:57.724Z] [000f] Closing log
[2014-08-22 02:25:57.724Z] [000f] Error parsing session log file, but it is not closed yet, will retry
[2014-08-22 02:25:57.724Z] [000f] Waiting for log update and dispatching events for 500
[2014-08-22 02:25:58.225Z] [000f] Opening log without write sharing
[2014-08-22 02:25:58.225Z] [000f] Opening log with write sharing
[2014-08-22 02:25:58.225Z] [000f] Log opened
[2014-08-22 02:25:58.225Z] [000f] Skipping 10 nodes
[2014-08-22 02:25:58.225Z] [000f] Closing log
[2014-08-22 02:25:58.225Z] [000f] Error parsing session log file, but it is not closed yet, will retry
[2014-08-22 02:25:58.225Z] [000f] Waiting for log update and dispatching events for 500
[2014-08-22 02:25:58.725Z] [000f] Opening log without write sharing
[2014-08-22 02:25:58.725Z] [000f] Opening log with write sharing
[2014-08-22 02:25:58.725Z] [000f] Log opened
[2014-08-22 02:25:58.725Z] [000f] Skipping 10 nodes
[2014-08-22 02:25:58.725Z] [000f] Closing log
[2014-08-22 02:25:58.725Z] [000f] Error parsing session log file, but it is not closed yet, will retry
[2014-08-22 02:25:58.725Z] [000f] Waiting for log update and dispatching events for 500
[2014-08-22 02:25:59.225Z] [000f] Opening log without write sharing
[2014-08-22 02:25:59.225Z] [000f] Opening log with write sharing
[2014-08-22 02:25:59.225Z] [000f] Log opened
[2014-08-22 02:25:59.225Z] [000f] Skipping 10 nodes
[2014-08-22 02:25:59.225Z] [000f] Closing log
[2014-08-22 02:25:59.225Z] [000f] Error parsing session log file, but it is not closed yet, will retry
[2014-08-22 02:25:59.225Z] [000f] Waiting for log update and dispatching events for 500
[2014-08-22 02:25:59.725Z] [000f] Opening log without write sharing
[2014-08-22 02:25:59.725Z] [000f] Opening log with write sharing
[2014-08-22 02:25:59.725Z] [000f] Log opened
[2014-08-22 02:25:59.725Z] [000f] Skipping 10 nodes
[2014-08-22 02:25:59.725Z] [000f] Closing log
[2014-08-22 02:25:59.725Z] [000f] Error parsing session log file, but it is not closed yet, will retry
[2014-08-22 02:25:59.725Z] [000f] Waiting for log update and dispatching events for 500
[2014-08-22 02:26:00.220Z] [0005] ExeSessionProcess.ProcessEvent entering
[2014-08-22 02:26:00.220Z] [0005] Scheduling output: [drwxr-xr-x 2 1001 1002 708608 Aug 22 2:23:00 2014 .]
[2014-08-22 02:26:00.220Z] [000f] Output: [drwxr-xr-x 2 1001 1002 708608 Aug 22 2:23:00 2014 .]
[2014-08-22 02:26:00.220Z] [0005] ExeSessionProcess.ProcessEvent leaving
[2014-08-22 02:26:00.220Z] [0005] ExeSessionProcess.ProcessEvent entering
[2014-08-22 02:26:00.220Z] [0005] Scheduling output: [drwxr-xr-x 3 0 0 4096 Apr 7 17:14:47 2014 ..]
[2014-08-22 02:26:00.220Z] [0005] ExeSessionProcess.ProcessEvent leaving
[2014-08-22 02:26:00.220Z] [000f] Output: [drwxr-xr-x 3 0 0 4096 Apr 7 17:14:47 2014 ..]
[2014-08-22 02:26:00.220Z] [0005] ExeSessionProcess.ProcessEvent entering
[2014-08-22 02:26:00.220Z] [0005] Scheduling output: [-rw-r--r-- 1 1001 1002 3495 Aug 22 0:41:40 2014 LP_2014-08-21T12-44-30Z_1.json]
I have debug logging enabled thus:
session.DebugLogPath = Path.GetDirectoryName([Assembly].GetExecutingAssembly().Location) + "\sftpGet.log"
This process has been working very reliably until this weekend when the debuglog (sftpGet.log) grew until the disk capacity (100 GByte) was exceeded. The log file was 84 GByte at this stage, so I hope that you will forgive me if I don't attach it. I have however included the head of this file below.
To clear the problem I stopped the service, moved the log file (I have retained it in case you have any suggestions about how to retrieve useful info from such a large file), got about 6000 files using WinSCP.exe, restarted the service, and everything has run as normal since then.
Is there a way to limit the size of the debuglog to prevent this problem from happening?
Thanks, Brian
[2014-08-22 02:25:56.215Z] [000f] Executing Assembly: WinSCPnet, Version=1.1.6.4433, Culture=neutral, PublicKeyToken=xxx; Path: C:\Program Files\WinSCPnet.DLL; Location: C:\Program Files\WinSCPnet.dll; Product: 5.5.4.0
[2014-08-22 02:25:56.215Z] [000f] Entry Assembly: AmbitSFTP, Version=1.7.16.1030, Culture=neutral, PublicKeyToken=null
[2014-08-22 02:25:56.215Z] [000f] Operating system: Microsoft Windows NT 6.2.9200.0
[2014-08-22 02:25:56.216Z] [000f] User: SYSTEM; Interactive: False
[2014-08-22 02:25:56.216Z] [000f] Runtime: 4.0.30319.34209
[2014-08-22 02:25:56.216Z] [000f] Console encoding: Input: Western European (Windows) (1252); Output: Western European (Windows) (1252)
[2014-08-22 02:25:56.216Z] [000f] Working directory: C:\Windows\system32
[2014-08-22 02:25:56.223Z] [000f] Session.ListDirectory entering
[2014-08-22 02:25:56.223Z] [000f] Command: [ls -- "/deliver/"]
[2014-08-22 02:25:56.223Z] [000f] ExeSessionProcess.ExecuteCommand entering
[2014-08-22 02:25:56.223Z] [000f] ExeSessionProcess.ExecuteCommand leaving
[2014-08-22 02:25:56.223Z] [0005] Scheduling output: [winscp> ls -- "/deliver/"]
[2014-08-22 02:25:56.223Z] [000f] SessionLogReader.Read entering
[2014-08-22 02:25:56.223Z] [000f] Read node 8: Whitespace
[2014-08-22 02:25:56.223Z] [000f] Log contents:
<?xml version="1.0" encoding="UTF-8"?>
<session xmlns="https://winscp.net/schema/session/1.0" name="xxx@999" start="2014-08-21T14:25:54.290Z">
<group name="open -hostkey="ssh-rsa 2048 9f:31:79:28:etc" -timeout=15 sftp://xxx:***@999" start="2014-08-21T14:25:55.862Z">
</group>
[2014-08-22 02:25:56.223Z] [000f] SessionLogReader.Read leaving
[2014-08-22 02:25:56.223Z] [000f] SessionLogReader.Read entering
[2014-08-22 02:25:56.223Z] [000f] Closing log
[2014-08-22 02:25:56.223Z] [000f] Error parsing session log file, but it is not closed yet, will retry
[2014-08-22 02:25:56.223Z] [000f] Waiting for log update and dispatching events for 125
[2014-08-22 02:25:56.223Z] [000f] Output: [winscp> ls -- "/deliver/"]
[2014-08-22 02:25:56.348Z] [000f] Opening log without write sharing
[2014-08-22 02:25:56.348Z] [000f] Opening log with write sharing
[2014-08-22 02:25:56.348Z] [000f] Log opened
[2014-08-22 02:25:56.348Z] [000f] Skipping 8 nodes
[2014-08-22 02:25:56.348Z] [000f] Read node 9: Element group
[2014-08-22 02:25:56.348Z] [000f] Log contents:
<?xml version="1.0" encoding="UTF-8"?>
<session xmlns="https://winscp.net/schema/session/1.0" name="xxx@999" start="2014-08-21T14:25:54.290Z">
<group name="open -hostkey="ssh-rsa 2048 9f:31:79:28:a7:etc" -timeout=15 sftp://xxx:***@999" start="2014-08-21T14:25:55.862Z">
</group>
<group name="ls -- "/deliver/"" start="2014-08-21T14:25:56.223Z">
[2014-08-22 02:25:56.348Z] [000f] SessionLogReader.Read leaving
[2014-08-22 02:25:56.348Z] [000f] SessionLogReader.Read entering
[2014-08-22 02:25:56.348Z] [000f] Read node 10: Whitespace
[2014-08-22 02:25:56.348Z] [000f] Log contents has not changed
[2014-08-22 02:25:56.348Z] [000f] SessionLogReader.Read leaving
[2014-08-22 02:25:56.348Z] [000f] SessionLogReader.Read entering
[2014-08-22 02:25:56.349Z] [000f] Closing log
[2014-08-22 02:25:56.349Z] [000f] Error parsing session log file, but it is not closed yet, will retry
[2014-08-22 02:25:56.349Z] [000f] Waiting for log update and dispatching events for 125
[2014-08-22 02:25:56.474Z] [000f] Opening log without write sharing
[2014-08-22 02:25:56.474Z] [000f] Opening log with write sharing
[2014-08-22 02:25:56.474Z] [000f] Log opened
[2014-08-22 02:25:56.474Z] [000f] Skipping 10 nodes
[2014-08-22 02:25:56.474Z] [000f] Closing log
[2014-08-22 02:25:56.474Z] [000f] Error parsing session log file, but it is not closed yet, will retry
[2014-08-22 02:25:56.474Z] [000f] Waiting for log update and dispatching events for 250
[2014-08-22 02:25:56.724Z] [000f] Opening log without write sharing
[2014-08-22 02:25:56.724Z] [000f] Opening log with write sharing
[2014-08-22 02:25:56.724Z] [000f] Log opened
[2014-08-22 02:25:56.724Z] [000f] Skipping 10 nodes
[2014-08-22 02:25:56.724Z] [000f] Closing log
[2014-08-22 02:25:56.724Z] [000f] Error parsing session log file, but it is not closed yet, will retry
[2014-08-22 02:25:56.724Z] [000f] Waiting for log update and dispatching events for 500
[2014-08-22 02:25:57.224Z] [000f] Opening log without write sharing
[2014-08-22 02:25:57.224Z] [000f] Opening log with write sharing
[2014-08-22 02:25:57.224Z] [000f] Log opened
[2014-08-22 02:25:57.224Z] [000f] Skipping 10 nodes
[2014-08-22 02:25:57.224Z] [000f] Closing log
[2014-08-22 02:25:57.224Z] [000f] Error parsing session log file, but it is not closed yet, will retry
[2014-08-22 02:25:57.224Z] [000f] Waiting for log update and dispatching events for 500
[2014-08-22 02:25:57.724Z] [000f] Opening log without write sharing
[2014-08-22 02:25:57.724Z] [000f] Opening log with write sharing
[2014-08-22 02:25:57.724Z] [000f] Log opened
[2014-08-22 02:25:57.724Z] [000f] Skipping 10 nodes
[2014-08-22 02:25:57.724Z] [000f] Closing log
[2014-08-22 02:25:57.724Z] [000f] Error parsing session log file, but it is not closed yet, will retry
[2014-08-22 02:25:57.724Z] [000f] Waiting for log update and dispatching events for 500
[2014-08-22 02:25:58.225Z] [000f] Opening log without write sharing
[2014-08-22 02:25:58.225Z] [000f] Opening log with write sharing
[2014-08-22 02:25:58.225Z] [000f] Log opened
[2014-08-22 02:25:58.225Z] [000f] Skipping 10 nodes
[2014-08-22 02:25:58.225Z] [000f] Closing log
[2014-08-22 02:25:58.225Z] [000f] Error parsing session log file, but it is not closed yet, will retry
[2014-08-22 02:25:58.225Z] [000f] Waiting for log update and dispatching events for 500
[2014-08-22 02:25:58.725Z] [000f] Opening log without write sharing
[2014-08-22 02:25:58.725Z] [000f] Opening log with write sharing
[2014-08-22 02:25:58.725Z] [000f] Log opened
[2014-08-22 02:25:58.725Z] [000f] Skipping 10 nodes
[2014-08-22 02:25:58.725Z] [000f] Closing log
[2014-08-22 02:25:58.725Z] [000f] Error parsing session log file, but it is not closed yet, will retry
[2014-08-22 02:25:58.725Z] [000f] Waiting for log update and dispatching events for 500
[2014-08-22 02:25:59.225Z] [000f] Opening log without write sharing
[2014-08-22 02:25:59.225Z] [000f] Opening log with write sharing
[2014-08-22 02:25:59.225Z] [000f] Log opened
[2014-08-22 02:25:59.225Z] [000f] Skipping 10 nodes
[2014-08-22 02:25:59.225Z] [000f] Closing log
[2014-08-22 02:25:59.225Z] [000f] Error parsing session log file, but it is not closed yet, will retry
[2014-08-22 02:25:59.225Z] [000f] Waiting for log update and dispatching events for 500
[2014-08-22 02:25:59.725Z] [000f] Opening log without write sharing
[2014-08-22 02:25:59.725Z] [000f] Opening log with write sharing
[2014-08-22 02:25:59.725Z] [000f] Log opened
[2014-08-22 02:25:59.725Z] [000f] Skipping 10 nodes
[2014-08-22 02:25:59.725Z] [000f] Closing log
[2014-08-22 02:25:59.725Z] [000f] Error parsing session log file, but it is not closed yet, will retry
[2014-08-22 02:25:59.725Z] [000f] Waiting for log update and dispatching events for 500
[2014-08-22 02:26:00.220Z] [0005] ExeSessionProcess.ProcessEvent entering
[2014-08-22 02:26:00.220Z] [0005] Scheduling output: [drwxr-xr-x 2 1001 1002 708608 Aug 22 2:23:00 2014 .]
[2014-08-22 02:26:00.220Z] [000f] Output: [drwxr-xr-x 2 1001 1002 708608 Aug 22 2:23:00 2014 .]
[2014-08-22 02:26:00.220Z] [0005] ExeSessionProcess.ProcessEvent leaving
[2014-08-22 02:26:00.220Z] [0005] ExeSessionProcess.ProcessEvent entering
[2014-08-22 02:26:00.220Z] [0005] Scheduling output: [drwxr-xr-x 3 0 0 4096 Apr 7 17:14:47 2014 ..]
[2014-08-22 02:26:00.220Z] [0005] ExeSessionProcess.ProcessEvent leaving
[2014-08-22 02:26:00.220Z] [000f] Output: [drwxr-xr-x 3 0 0 4096 Apr 7 17:14:47 2014 ..]
[2014-08-22 02:26:00.220Z] [0005] ExeSessionProcess.ProcessEvent entering
[2014-08-22 02:26:00.220Z] [0005] Scheduling output: [-rw-r--r-- 1 1001 1002 3495 Aug 22 0:41:40 2014 LP_2014-08-21T12-44-30Z_1.json]
