Bug? Timestamp issue: Files downloaded between 12am and 1am :: Support Forum

lonely188 Guest

Bug? Timestamp issue: Files downloaded between 12am and 1am

2016-09-08 19:57

I am having a Date Modified timestamp issue. All files downloaded have their correct Date Modified in windows explorer, except anything that was posted on the FTP between 12am and 1am. All of those files have their minute value set to 00. So instead of a file being written locally with 12:28am, it is written with 12:00am.

So if I use session.ListDirectory, the timestamps on the files I am downloading come up with the correct hour and minute.
When I use session.GetFiles, the downloaded files come reset to 12:00am for any files between 12am and 1am, all the others are correct though.

< 2016-09-07 00:36:17.231 150 Here comes the directory listing.
< 2016-09-07 00:36:17.231 226 Directory send OK.
. 2016-09-07 00:36:17.231 drwxr-xr-x    2 ftp      ftp          4096 Sep 07 00:28 .
. 2016-09-07 00:36:17.231 drwxr-xr-x    2 ftp      ftp          4096 Sep 07 00:28 ..
. 2016-09-07 00:36:17.231 -rw-------    1 ftp      ftp       1813856 Sep 07 00:28 TEST0906.ZIP
. 2016-09-07 00:36:17.247 Directory listing successful
. 2016-09-07 00:36:17.247 ..;D;0;1899-12-30T06:00:00.000Z;"" [0];"" [0];---------;0
. 2016-09-07 00:36:17.247 TEST0906.ZIP;-;1813856;2016-09-07T10:28:00.000Z;"ftp" [0];"ftp" [0];rw-------;0
< 2016-09-07 00:36:17.262 Script: D---------   0                           0              ..
< 2016-09-07 00:36:17.278 Script: -rw-------   0 ftp      ftp        1813856 Sep  7  5:28:00 2016 TEST0906.ZIP
> 2016-09-07 00:36:17.434 Script: get  -nopermissions -preservetime -transfer="binary" -- ".//TEST0906.ZIP" "C:\"
. 2016-09-07 00:36:17.434 Listing file ".//TEST0906.ZIP".
. 2016-09-07 00:36:17.434 Retrieving file information...
> 2016-09-07 00:36:17.434 PWD
< 2016-09-07 00:36:17.434 257 "/"
> 2016-09-07 00:36:17.434 CWD /TEST0906.ZIP
< 2016-09-07 00:36:17.434 550 Failed to change directory.
> 2016-09-07 00:36:17.434 TYPE I
< 2016-09-07 00:36:17.434 200 Switching to Binary mode.
> 2016-09-07 00:36:17.434 SIZE /TEST0906.ZIP
< 2016-09-07 00:36:17.434 213 1813856
> 2016-09-07 00:36:17.450 MDTM /TEST0906.ZIP
< 2016-09-07 00:36:17.450 213 20160907002849
. 2016-09-07 00:36:17.450 Retrieving file information successful
. 2016-09-07 00:36:17.450 TEST0906.ZIP;-;1813856;2016-09-07T05:00:00.000Z;"" [0];"" [0];---------;0
. 2016-09-07 00:36:17.450 Copying 1 files/directories to local directory "C:\"
. 2016-09-07 00:36:17.450   PrTime: Yes; PrRO: No; Rght: rw-r--r--; PrR: No (No); FnCs: N; RIC: 0100; Resume: S (102400); CalcS: No; Mask: 
. 2016-09-07 00:36:17.450   TM: B; ClAr: No; RemEOF: No; RemBOM: No; CPS: 0; NewerOnly: No; InclM: ; ResumeL: 0
. 2016-09-07 00:36:17.450   AscM: *.*html; *.htm; *.txt; *.php; *.php3; *.cgi; *.c; *.cpp; *.h; *.pas; *.bas; *.tex; *.pl; *.js; .htaccess; *.xtml; *.css; *.cfg; *.ini; *.sh; *.xml
. 2016-09-07 00:36:17.465 File: '//TEST0906.ZIP' [2016-09-07T05:00:00.000Z] [1813856]
. 2016-09-07 00:36:17.465 Copying "//TEST0906.ZIP" to local directory started.
. 2016-09-07 00:36:17.465 Binary transfer mode selected.
. 2016-09-07 00:36:17.481 Starting download of /TEST0906.ZIP
> 2016-09-07 00:36:17.481 TYPE I
< 2016-09-07 00:36:17.496 200 Switching to Binary mode.
> 2016-09-07 00:36:17.496 PASV
< 2016-09-07 00:36:17.496 227 Entering Passive Mode (192,168,111,2,99,196).
> 2016-09-07 00:36:17.496 RETR TEST0906.ZIP
< 2016-09-07 00:36:17.496 150 Opening BINARY mode data connection for TEST0906.ZIP (1813856 bytes).
< 2016-09-07 00:36:17.543 226 Transfer complete.
. 2016-09-07 00:36:17.668 Download successful
. 2016-09-07 00:36:17.668 Transfer done: '//TEST0906.ZIP' [1813856]

So these couple of lines from the log above show that the time is losing its minutes when downloading (2016-09-07T05:00:00.000Z):

. 2016-09-07 00:36:17.450 TEST0906.ZIP;-;1813856;2016-09-07T05:00:00.000Z;"" [0];"" [0];---------;0
. 2016-09-07 00:36:17.465 File: '//TEST0906.ZIP' [2016-09-07T05:00:00.000Z] [1813856]

Where just before the download, it shows the correct time: Sep 07 00:28 TEST0906.ZIP
or from the script line Sep 7 5:28:00 2016 TEST0906.ZIP

Any idea what might be causing this? Thanks!

Reply with quote

lonely188 Guest

2016-09-13 19:54

If it helps, I am using PowerShell to run this. Also sorry about the subject of the topic. 'Downloaded' isn't the proper term, it should be 'Posted'. It doesn't matter when the files are downloaded, the issue occurs if the files themselves were posted between 12am and 1am and have those modify times.

Reply with quote

martin◆ Site Admin
Joined:: 2002-12-10
Posts:: 41,518
Location:: Prague, Czechia

Re: Bug? Timestamp issue: Files downloaded between 12am and 1am

2016-09-14

Thanks for your post.
What version of WinSCP are you using? Did you try the latest one?
Please attach a complete session log file.

Reply with quote

lonely188 Guest

2016-09-14 20:02

The files I was working with have been removed from the FTP so I no longer have any files with modification dates between 12am and 1am.

I have been using WinSCP 5.7.3 but I tried it with latest version and still had the issue. But I did just discover that if you load an assembly into PowerShell, and then try to add the same assembly but different version, it does not overwrite the previous, instead appends the assemble to the AppDomain. It appears PowerShell uses the assembly that was loaded first if duplicate assembly types were added. So I may have actually not tested it with the latest 5.9.1 release since I probably tested in the same PoSh session (with both WinSCP versions loaded).

Also, can you explain this... Using the GUI client (v5.9.1), If I take that file that was downloaded and has a 12:00am timestamp, upload it to the same FTP, it becomes timestamped as 5:00am. But if I create a 'New Text Document.txt' which has a timestamp of 1:45pm and upload it to the same FTP, it indeed stays timestamped as 1:45pm. How can that other file change its timestamp?

I'm not sure when the next time I will see a file posted between 12am - 1am. I'll see if I can post one myself.

Reply with quote

lonely188 Guest

2016-09-14 20:48

I was able to find the log from last week. Full log is attached.

I would like to use the latest 5.9.1 version but I tried to switch in the past and ran into a bunch of timestamp offset issues. Maybe you could shed some light on this if I provide additional details?

WinSCP_Session_2016-09-07.log (39.93 KB, Private file)

Reply with quote

martin◆ Site Admin

2016-09-15

lonely188 wrote:

I would like to use the latest 5.9.1 version but I tried to switch in the past and ran into a bunch of timestamp offset issues. Maybe you could shed some light on this if I provide additional details?

What issues?

Reply with quote

lonely188 Guest

2016-09-15 15:42

martin wrote:

lonely188 wrote:

I would like to use the latest 5.9.1 version but I tried to switch in the past and ran into a bunch of timestamp offset issues. Maybe you could shed some light on this if I provide additional details?
What issues?

So the first time I switched to 5.9.1 from 5.7.3, I had issues with the timestamps on files being off in both the GUI and assembly. So after some research I found setting the MLSD command to 'OFF' and unchecking 'Detect automatically' timezone checkbox gave me the correct times listed in my GUI sessions. My FTP server doesn't appear to support MLSD. Files now appear correct and download with the correct timestamps when using the 5.9.1 GUI.

The issue that I am having is with the assembly:

5.7.3:
Default SessionOptions
List Time: 9:05 pm - WRONG
Download Time: 4:05 pm - CORRECT

SessionOptions = TimeDifferenceAuto 0 / FtpUseMlsd 1
List Time: 4:05 pm - CORRECT
Download Time: 11:05 am - WRONG

5.9.1:
Default SessionOptions
List Time: 11:05 am - WRONG
Download Time: 11:05 am - WRONG

SessionOptions = TimeDifferenceAuto 0 / FtpUseMlsd 1
List Time: 4:05 pm - CORRECT
Download Time: 11:05 am - WRONG

So in 5.7.3, I would use the Default SessionOptions since the download times were correct. For the List times, I just applied the PowerShell command [DateTime]::Parse($File.LastWriteTime,$null,"AssumeUniversal") to correct the list times. But in 5.9.1, I have no method to get the correct download times that I know of. Can you help me with what I should be adjusting to correct the download times?

Thanks!

Reply with quote

lonely188 Guest

v5.7.3 appears to be the issue for the 12am - 1am timestamp problem

2016-09-16 21:56

Ok I got a chance to test the 12am - 1am issue again. So I ran version 5.7.3 and reproduced the issue of the minutes resetting to 00. The file was posted at 12:27am, when downloaded with v5.7.3, file has a timestamp of 12:00am on the local disk. I tried downloading with version 5.9.1 and it looks like the minutes stayed, but like in my previous post, my hours are offset in 5.9.1, so the file is timestamped as 7:27pm (5hrs behind).

I was playing around a bit in PowerShell with this, and I do have a fix I could use (but I would much rather prefer a setting I could tweak for WinSCP if there is one). I came up with this code to re-timestamp the file by using the Utc time assumed as local:

Get-Item $RecievedFiles | % {$_.LastWriteTime = [DateTime]::Parse($_.LastWriteTimeUtc,$null,"AssumeLocal")}

It works, but if there's a way to fix the heart of the problem by tweaking a WinSCP setting, that would be even better!
Thanks for hearing me out so far.

Reply with quote

martin◆ Site Admin

2016-09-19

So can you please post a log from 5.9.1 (or actually 5.9.2 already) with the default settings (auto detection turned on)?
Name one file with a wrong time. Tell us, what time do you see, what time do you expect and why.

Reply with quote

lonely188 Guest

5.9.2

2016-09-19 17:01

martin wrote:

So can you please post a log from 5.9.1 (or actually 5.9.2 already) with the default settings (auto detection turned on)?
Name one file with a wrong time. Tell us, what time do you see, what time do you expect and why.

I'm in Central Time (US & Canada).
Attached is the session log and a screenshot of the localdisk timestamp of the file after it is downloaded. I named the file 1228am.ZIP.
I'm seeing a time of 9/15/2016 7:28pm, I expect 9/16/2016 12:28am, I expect that time because that is the time the file was posted to our FTP.

Localdisk timestamp after download.png (1.8 KB, Private file)

WinSCP_Session.log (8.76 KB)

Reply with quote

martin◆ Site Admin
Joined:: 2002-12-10
Posts:: 41,518
Location:: Prague, Czechia

Re: 5.9.2

2016-09-22

The server reports 2016-09-16 00:28:53 GMT:

> 2016-09-19 10:42:06.825 MDTM /1228am.ZIP
< 2016-09-19 10:42:06.825 213 20160916002853

What is 2016-09-15 19:28:53 GMT-5:
So it looks like WinSCP behaves correctly.

If the server is really wrong, you will indeed need to override the time zone offset to -5.

Reply with quote

lonely188 Guest

SUCCESS! THANK YOU!

2016-09-22 20:25

martin wrote:

The server reports 2016-09-16 00:28:53 GMT:

Ahhh! I think I understand now what's happening. Since the server reports 12:28am in GMT time, but I'm really in central time, it's going to be wrong because realistically, 12:28am CDT is really 5:28am GMT. So I would need the server time to actually report its time as 5:28am GMT. I looked at my server and its running as CDT, but after Googling a bit, I learned something new about the FTP protocol: it does not include timezone information. I did not know this.

So with further Googling, I found that I could changed VSFTPD setting of 'use_localtime' to NO, and now all my file listings and download timestamps are correct! I also updated the GUI to go back to 'Detect Automatically' and those times are correct now as well. And now I can even post a file that was downloaded from the FTP, back to the FTP and the time is correct too! Crazy how a simple 'YES' 'NO' can make a world of a difference. Now I can use the latest version!

Thanks so much for all your help, and time!

Reply with quote