Impossible to set loglevel for synchronize job

Hi,

I previously use WinSCP Version 4.3.9 (Build 1817)

i have upgraded software to WinSCP Version 5.9.5 and last version WinSCP Version 5.9.6.

I use this script
open Internet_FR
cd /WEBCUC/cybershop/abix/www/prod/05
lcd H:\WEB\Cybershop\abix\www\prod\05
synchronize remote
exit

In old version (4.3.9), LOG generated are really light in Normal mode.
In new version (5.9.5), LOG is more larger (upper than debug 2 in old version).

I try using WINSCP interface to set 3 differents modes : Normal / Debug 1 / Debug 2
Setting have no effect on file size
I try also command parameter /loglevel=0, /loglevel=1, /loglevel=2
LOG File is allways created with the same size.

That's why i think default mode is allways the most detailled debug mode.
See file ZIP Attached

It's a problem because my original job synchronize more than 50 folders and
LOG size is around 350 MB to 500 MB

Thank you by advance for your support.

BR
Patrick

I'm sorry that you have problems with sites of the log.

But it's as it is. The log includes necessary information to debug problems with synchronization. Without all these details, the log file is useless for debugging.

martin wrote:

I'm sorry that you have problems with sites of the log.

But it's as it is. The log includes necessary information to debug problems with synchronization. Without all these details, the log file is useless for debugging.

Hi Martin

Ok i understand the purpose of LOG. But when i obtain a LOG larger than 300 MB, how i can debug if i cannot open the file with any text editor ???

Why do you have 3 differents settings for log details : Normal / Debug 1 / Debug 2, if log file created have allways the same size ? In older version of Winscp, this feature works correctly.

Sorry to insist
Please Check logs attached....

BR
Patrick

PBERNARD wrote:

Why do you have 3 differents settings for log details : Normal / Debug 1 / Debug 2, if log file created have allways the same size ? In older version of Winscp, this feature works correctly.

No, it was not working correctly. Previously the Normal level log file with FTP protocol did not provide enough information even for a trivial debugging.

martin wrote:

PBERNARD wrote:

Why do you have 3 differents settings for log details : Normal / Debug 1 / Debug 2, if log file created have allways the same size ? In older version of Winscp, this feature works correctly.

No, it was not working correctly. Previously the Normal level log file with FTP protocol did not provide enough information even for a trivial debugging.

Hi Martin,

I'am really disapointed by your answer. I give you a proof you have a little bug ("log details setting have no effect on log file size") and you say No i have no bug.

As you want, it's your software ... not mine ... In my opinion, you should Listen more to improve user experience of your software. I browse your forum and i see a lot of posts with the same issue on huge Log with no solution.

I'am sorry, i prefer cancel WinSCP and switch to an another software like ScriptFTP.

BR
Patrick

martin wrote:

Without all these details, the log file is useless for debugging.

I think there's a real issue here that - whilst it's an enhancement request, not really a bug - should be addressed. Put simply, the log file generated by WinSCP (at loglevel=0), for some purposes (e.g. simple monitoring of whether a historical operation succeeded or otherwise) is too verbose to be usable when running repeatedly as a scheduled task, and including operations which include things like file synchronisation: and I do NOT agree with the statement that removing some of this verbosity would make it "useless".

I appreciate the current loglevel probably IS what you would need if you wanted to do an in-depth analysis of (a) every operation WinSCP performed and (b) the detail of every response it got while performing those operations, including any sub-steps it took to achieve those operations - but for lots of other software the log files do NOT show (b) - they simply record the requested action, and then whether that action was performed successfully or otherwise (if the action failed adding more detail such as the error itself).

A good example is running a repeated WinSCP command line script which includes something like this:

> rm "T2tdata_i????????T??????Z.zip"<2018-01-02

The log file goes on to list every file individually which either matches or does not match the file-pattern filter e.g. multiple lines like this:

> type=file;size=429;modify=20180104110346;UNIX.mode=0644;UNIX.uid=1088;UNIX.gid=1090;unique=803g5d80420; T2tdata_i20180104T110344Z.zip

eventually it states this:

> Directory listing successful

it then lists the matching files again (presumably now analysing the modified times) i.e. multiple lines like this:

> T2tdata_i20180103T003534Z.zip;-;291;2018-01-03T00:35:37.000Z;3;"1088" [0];"1090" [0];rw-r--r--;0

and then eventually you get something like this:

> Script: No file matching 'T2tdata_i????????T??????Z.zip<2018-01-02' found.

in the example above, that single operation took 303 lines to record in the log (as a side-issue I suspect the recording of the log at this level of detail might be slowing down the script).

there is clearly an argument - in my view - to introduce some kind of WinSCP loglevel (e.g. "-1") which simply records requested actions and end result e.g. in the case above just:

> rm "T2tdata_i????????T??????Z.zip"<2018-01-02
> Script: No file matching 'T2tdata_i????????T??????Z.zip<2018-01-02' found.

but still - if an error arises - then listing details of what the error is. it's not uncommon to even see stuff like this in other software logs:

> loglevel is currently set to -1 please set to 0 to record more detail about the requested operation

poke wrote:

I think there's a real issue here that - whilst it's an enhancement request, not really a bug - should be addressed. Put simply, the log file generated by WinSCP (at loglevel=0), for some purposes (e.g. simple monitoring of whether a historical operation succeeded or otherwise) is too verbose to be usable when running repeatedly as a scheduled task, and including operations which include things like file synchronisation: and I do NOT agree with the statement that removing some of this verbosity would make it "useless".

WinSCP session log file is intended for debugging purposes and for nothing else.
For tracking, please use XML log.
https://winscp.net/eng/docs/logging_xml

martin wrote:

WinSCP session log file is intended for debugging purposes and for nothing else.

there's no indication in the documentation that session logging is just for debugging, it explicitly states it's useful for connection problems AND debugging:
https://winscp.net/eng/docs/logging
"Session log: Events are logged in unstructured form with configurable level of verbosity. Information logged differ with protocol used. This format is useful to troubleshoot problems with connection. You should also include this log when reporting bugs or asking for support."

the problem myself and the author of the original post is reporting is that that "configurable level of verbosity" is not configurable enough in that loglevel zero is still far too verbose for many purposes

i have looked into the xml logging feature which you kindly pointed me towards, and whilst i can see that has great potential for some kinds of tasks (e.g. a remote system communicating with WinSCP to directly query the results of a task), it is not very readable for tech staff simply wishing to open a logfile on the local system and check the results, it always generates individual files for each action (again harder to manage / read), and also it does not always give details of every action attempted (e.g. in the specific case of the "rm" command I exampled above, with xmlgouping disabled i found that command did not even get reported in the logs when no files matching were found,a nd with xmlgrouping enabled it was listed but not reported as either a failure or success)

poke wrote:

there's no indication in the documentation that session logging is just for debugging, it explicitly states it's useful for connection problems AND debugging:
https://winscp.net/eng/docs/logging
"Session log: Events are logged in unstructured form with configurable level of verbosity. Information logged differ with protocol used. This format is useful to troubleshoot problems with connection. You should also include this log when reporting bugs or asking for support."

That's what I mean by "debugging".

i have looked into the xml logging feature which you kindly pointed me towards, and whilst i can see that has great potential for some kinds of tasks (e.g. a remote system communicating with WinSCP to directly query the results of a task), it is not very readable for tech staff simply wishing to open a logfile on the local system and check the results,

Why? And if you are not satisfied with the format, it's XML for a reason. You can use XSLT or similar method to convert the XML log to any format that suits you.
See https://winscp.net/eng/docs/logging_xml#parse

it always generates individual files for each action (again harder to manage / read), and also it does not always give details of every action attempted (e.g. in the specific case of the "rm" command I exampled above, with xmlgouping disabled i found that command did not even get reported in the logs when no files matching were found,a nd with xmlgrouping enabled it was listed but not reported as either a failure or success)

And this nicely summarizes the problem. You have a very very specific idea about a verbosity of details you want. And every other user will have a different idea. I cannot make everyone happy.

Btw by default, rm with a mask that does not match anything is a success, indicated by an absence of error. Had the rm failed (like if you provided a path to non-existing folder), you would see an failure tag. If you want to get failure tag even on no-match, use option failonnomatch on:
https://winscp.net/eng/docs/scriptcommand_option#failonnomatch

That's what I mean by "debugging".

"to troubleshoot problems with connection" and "debugging" to me are two different things; a connection issue could arise at any time (e.g. there is no internet connection) and is exactly the kind of thing technical staff would be reviewing the log files for; "debugging" implies more investigating potential issues with the WinSCP code itself

You can use XSLT or similar method to convert the XML log to any format that suits you

apart from the extra work involved in coding this, it means i have to know in advance which elements of the XML log i am interested in and which can be ignored; there are therefore forward-compatibility issues (what if the XML log at a later stage changes or enhances its structure)

You have a very very specific idea about a verbosity of details you want. And every other user will have a different idea

maybe it's just my limited experience but asking for a program log file which reports (a) the requested action and (b) any errors encountered processing that action is not a "way out" idea. what myself and (i believe) the original poster are requesting is that you give us a verbosity level that strips out all the internal stuff which trudges through how WinSCP goes about processing every requested action (the example of a synchronisation-type request being a very good example of just how verbose that approach is) and simply reports request and result

Had the rm failed (like if you provided a path to non-existing folder), you would see an failure tag. If you want to get failure tag even on no-match, use option failonnomatch

i can see arguments each way but to me requesting removal of any files matching a specified wildcard should not be considered as a 'failure' / error if the ftp connection succeeded, all files on the remote server were successfully listed, but no matching files were found i.e. this seems like a hack and not a sensible solution

OK, I'm taking your opinion into account.

See also https://winscp.net/tracker/1637