shutil.copyfile is incomplete (truncated)

[Rob Schneider]

Using Python 2.7.2 on OSX, I have created a file in temp space, then use the function "shutil.copyfile(fn,loc+fname)" from "fn" to "loc+fname".

At the destination location, the file is truncated. About 10% of the file is lost. Original file is unchanged.

I added calls to "statinfo" immediately after the copy, and all looks ok (correct file size).

filecmp.cmp(fn,loc+fname)
print "Statinfo :"+fn+":\n", os.stat(fn)
print "Statinfo :"+loc+fname+":\n", os.stat(loc+fname)

But when I look at the file in Finder, destination is smaller and even looking at the file (with text editor) file is truncated.

What could be causing this?

[Neil Cerutti]

Could fn be getting some changes written after the copy is made?

Is the file flushed/closed before you copy it?

--
Neil Cerutti

[Rob Schneider]

Thanks. Yes, there is a close function call before the copy is launched. No other writes.
Does Python wait for file close command to complete before proceeding?

[Neil Cerutti]

On 2013-04-11, Rob Schneider <rms...@gmail.com> wrote:

The close method is defined and flushing and closing a file, so
it should not return until that's done.

What command are you using to create the temp file?

--
Neil Cerutti

[Steven D'Aprano]

On Thu, 11 Apr 2013 19:55:53 +0000, Neil Cerutti wrote:

> On 2013-04-11, Rob Schneider <rms...@gmail.com> wrote:
>> Thanks. Yes, there is a close function call before the copy is
>> launched. No other writes. Does Python wait for file close command to
>> complete before proceeding?
>
> The close method is defined and flushing and closing a file, so it
> should not return until that's done.

But note that "done" in this case means "the file system thinks it is
done", not *actually* done. Hard drives, especially the cheaper ones,
lie. They can say the file is written when in fact the data is still in
the hard drive's internal cache and not written to the disk platter.
Also, in my experience, hardware RAID controllers will eat your data, and
then your brains when you try to diagnose the problem.

I would consider the chance that the disk may be faulty, or the file
system is corrupt. Does the problem go away if you write to a different
file system or a different disk?



--
Steven

[Cameron Simpson]

On 12Apr2013 00:06, Steven D'Aprano <steve+comp....@pearwood.info> wrote:
| On Thu, 11 Apr 2013 19:55:53 +0000, Neil Cerutti wrote:
| > On 2013-04-11, Rob Schneider <rms...@gmail.com> wrote:
| >> Thanks. Yes, there is a close function call before the copy is
| >> launched. No other writes. Does Python wait for file close command to
| >> complete before proceeding?
| >
| > The close method is defined and flushing and closing a file, so it
| > should not return until that's done.
|
| But note that "done" in this case means "the file system thinks it is
| done", not *actually* done.

Unless there's a reboot (or crash) in between, the view from the
app should be consistent and correct.

| Hard drives, especially the cheaper ones,
| lie. They can say the file is written when in fact the data is still in
| the hard drive's internal cache and not written to the disk platter.
| Also, in my experience, hardware RAID controllers will eat your data, and
| then your brains when you try to diagnose the problem.
|
| I would consider the chance that the disk may be faulty, or the file
| system is corrupt. Does the problem go away if you write to a different
| file system or a different disk?

Or that the filesystem may be full? Of course, that's usually obvious
more widely when it happens...

Question: is the size of the incomplete file a round number? (Like
a multiple of a decent sized power of 2>)

Cheers,
--
Cameron Simpson <c...@zip.com.au>

I am now convinced that theoretical physics is actual philosophy.
- Max Born

[Ned Deily]

In article <20130412011...@cskk.homeip.net>,

Cameron Simpson <c...@zip.com.au> wrote:
> Or that the filesystem may be full? Of course, that's usually obvious
> more widely when it happens...
>
> Question: is the size of the incomplete file a round number? (Like
> a multiple of a decent sized power of 2>)

Also on what OS X file system type does the file being created reside,
in particular, is it a network file system?

--
Ned Deily,
n...@acm.org

[Rob Schneider]

> The close method is defined and flushing and closing a file, so
>
> it should not return until that's done.
>
>
>
> What command are you using to create the temp file?
>
>

re command to write the file:
f=open(fn,'w')
... then create HTML text in a string
f.write(html)
f.close

[Rob Schneider]

> I would consider the chance that the disk may be faulty, or the file
>
> system is corrupt. Does the problem go away if you write to a different
>
> file system or a different disk?
>

It's a relatively new MacBook Pro with a solid state disk. I've not noticed any other disk problems. I did a "repair permissions" (for what it's worth). Maybe I'll have it tested at the Genius Bar. I don't have the full system on another computer to try that; but will work on that today.

[Rob Schneider]

>
> > Or that the filesystem may be full? Of course, that's usually obvious
>
> > more widely when it happens...
>
> >
>
> > Question: is the size of the incomplete file a round number? (Like
>
> > a multiple of a decent sized power of 2>)
>
>
>
> Also on what OS X file system type does the file being created reside,
>
> in particular, is it a network file system?
>

File system not full (2/3 of disk is free)

Source (correct one) is 47,970 bytes. Target after copy of 45,056 bytes. I've tried changing what gets written to change the file size. It is usually this sort of difference.

The file system is Mac OS Extended Journaled (default as out of the box).

[Rob Schneider]

> The file system is Mac OS Extended Journaled (default as out of the box).

I ran a repair disk .. .while it found and fixed what it called "minor" problems, it did something. However, the repair did not fix the problem. I just ran the program again and the source is 47,970 bytes and target after copy if 45,056.

Interestingly, the test I run just after the copy , i run a file compare:

code:

if showproperties:
print "Filecompare :",filecmp.cmp(fn,loc+fname)

print "Statinfo :"+fn+":\n", os.stat(fn)
print "Statinfo :"+loc+fname+":\n", os.stat(loc+fname)

results:

Filecompare : True
Statinfo :/var/folders/p_/n5lktj2n0r938_46jyqb52g40000gn/T/speakers.htm:
posix.stat_result(st_mode=33188, st_ino=32205850, st_dev=16777218L, st_nlink=1, st_uid=501, st_gid=20, st_size=45056, st_atime=1365749178, st_mtime=1365749178, st_ctime=1365749178)
Statinfo :/Users/rmschne/Documents/ScottishOilClub/SOC Board Doc Sharing Folder/Meetings/speakers.htm:
posix.stat_result(st_mode=33188, st_ino=32144179, st_dev=16777218L, st_nlink=1, st_uid=501, st_gid=20, st_size=45056, st_atime=1365749178, st_mtime=1365749178, st_ctime=1365749178)

It shows file size 45,056 on both source and target, which is the file size of the flawed target, and is not what Finder shows for source.

Sigh.

[Rob Schneider]

> The file system is Mac OS Extended Journaled (default as out of the box).

[Rob Schneider]

>
> > Or that the filesystem may be full? Of course, that's usually obvious
>
> > more widely when it happens...
>
> >
>
> > Question: is the size of the incomplete file a round number? (Like
>
> > a multiple of a decent sized power of 2>)
>
>
>
> Also on what OS X file system type does the file being created reside,
>
> in particular, is it a network file system?
>

File system not full (2/3 of disk is free)

Source (correct one) is 47,970 bytes. Target after copy of 45,056 bytes. I've tried changing what gets written to change the file size. It is usually this sort of difference.

[Chris Angelico]

Hold it one moment... You're not actually calling close. The file's
still open. Is that a copy/paste problem, or is that your actual code?

In Python, a function call ALWAYS has parentheses after it. Evaluating
a function's name like that returns the function (or method) object,
which you then do nothing with. (You could assign it someplace, for
instance, and call it later.) Try adding empty parens:

f.close()

and see if that solves the problem. Alternatively, look into the
'with' statement and the block syntax that it can give to I/O
operations.

ChrisA

[Ned Deily]

In article <6eeabeb2-e6dd-49fc...@googlegroups.com>,

Rob Schneider <rms...@gmail.com> wrote:
> > The file system is Mac OS Extended Journaled (default as out of the box).

> It shows file size 45,056 on both source and target, which is the file size
> of the flawed target, and is not what Finder shows for source.

Perhaps the source file has an OS X resource fork or other extended
attribute metadata. shutil's copy functions won't handle those. One
way to see if that is the case is to examine the source file in a
terminal window with: ls -l@

$ ls -l@ test.jpg
-rw-r--r--@ 1 nad staff 40359 Jul 15 2009 test.jpg
com.apple.FinderInfo 32
com.apple.ResourceFork 899489

--
Ned Deily,
n...@acm.org

[Cameron Simpson]

On 11Apr2013 23:32, Rob Schneider <rms...@gmail.com> wrote:
| > > Question: is the size of the incomplete file a round number? (Like
| > > a multiple of a decent sized power of 2>)

[...]

| Source (correct one) is 47,970 bytes. Target after copy of 45,056
| bytes. I've tried changing what gets written to change the file
| size. It is usually this sort of difference.

45046 is exactly 11 * 4096. I'd say your I/O is using 4KB blocks,
and the last partial block (to make it up to 47970) didn't get
written (at the OS level).

Earlier you wrote:
| I have created a file in temp space, then use the function
| "shutil.copyfile(fn,loc+fname)" from "fn" to "loc+fname".

and:

| Yes, there is a close function call before the copy is launched. No other writes.
| Does Python wait for file close command to complete before proceeding?

Please show us the exact code used to make the temp file.

I would guess the temp file has not been closed (or flushed) before
the call to copyfile.

If you're copying data to a tempfile, it will only have complete
buffers (i.e. multiples of 4096 bytes) in it until the final flush
or close.

So I'm imagining something like:

tfp = open(tempfilename, "w")
... lots of tfp.write() ...
shutil.copyfile(tempfilename, newfilename)

Note above no flush or close of tfp. So the final incomplete I/O
buffer is still in Python's memory; it hasn't been actually written
to the temp file because the buffer has not been filled, and the file
has not been closed.

Anyway, can you show us the relevant bits of code involved?

Cheers,
--
Cameron Simpson <c...@zip.com.au>

Processes are like potatoes. - NCR device driver manual

[Rob Schneider]

Thanks for the observation.

Code (simplified but results in same flaw) (which a close, far as I can tell).

def CreateSpeakerList1():
import shutil
import filecmp
import os.path

t=get_template('speaker_list.html')
fn=TEMP_DIR+SOC_SPEAKER_LIST
fn=tempfile.gettempdir()+"/"+SOC_SPEAKER_LIST
f=open(fn,'w')
speaker_list=Speaker.objects.order_by('status__order','targetmtg__date')
print " Creating " + SOC_SPEAKER_LIST + " ..."
html=(smart_str(t.render(Context(
{
'css_include_file':CSS_INCLUDE_FILE,
'css_link':False,
'title': ORG_NAME+" Speaker List",
'speaker_list': speaker_list,
}))))
f.write(html)
f.close
print " Wrote "+fn
shutil.copyfile(fn,SOC_GENERAL_OUTPUT_FOLDER+SOC_SPEAKER_LIST)
print "Filecompare :",filecmp.cmp(fn,SOC_GENERAL_OUTPUT_FOLDER+SOC_SPEAKER_LIST)

print "Statinfo :"+fn+":\n", os.stat(fn)

print "Statinfo :"+SOC_GENERAL_OUTPUT_FOLDER+SOC_SPEAKER_LIST+"\n", os.stat(SOC_GENERAL_OUTPUT_FOLDER+SOC_SPEAKER_LIST)
return

Output on latest run:

Creating speakers.htm ...
Wrote /var/folders/p_/n5lktj2n0r938_46jyqb52g40000gn/T/speakers.htm
Filecompare : True
Statinfo :/var/folders/p_/n5lktj2n0r938_46jyqb52g40000gn/T/speakers.htm:
posix.stat_result(st_mode=33188, st_ino=32332374, st_dev=16777218L, st_nlink=1, st_uid=501, st_gid=20, st_size=45056, st_atime=1365758139, st_mtime=1365758139, st_ctime=1365758139)
Statinfo :/Users/rmschne/Documents/ScottishOilClub/Output/speakers.htm
posix.stat_result(st_mode=33188, st_ino=32143886, st_dev=16777218L, st_nlink=1, st_uid=501, st_gid=20, st_size=45056, st_atime=1365758029, st_mtime=1365758139, st_ctime=1365758139)

[Rob Schneider]

[Chris Angelico]

On Fri, Apr 12, 2013 at 7:18 PM, Rob Schneider <rms...@gmail.com> wrote:
> f.close

Yep, there's the problem! See my previous post for details. Change this to:

f.close()

and you should be sorted.

ChrisA

[Rob Schneider]

Slapping forehead ... hard. Thanks!

[Rob Schneider]

On Friday, 12 April 2013 10:22:21 UTC+1, Chris Angelico wrote:

[Mark Lawrence]

a) We've all done it :)
b) The print function/statement or Python's interactive mode are awesome
in situations like this.

--
If you're using GoogleCrap� please read this
http://wiki.python.org/moin/GoogleGroupsPython.

Mark Lawrence

[Roy Smith]

In article <mailman.506.1365751...@python.org>,

Rob Schneider <rms...@gmail.com> wrote:

> Source (correct one) is 47,970 bytes. Target after copy of 45,056 bytes.
> I've tried changing what gets written to change the file size. It is usually
> this sort of difference.
>
> The file system is Mac OS Extended Journaled (default as out of the box).

Is it always the tail end of the file that gets truncated, or is it
missing (or mutating) data in the middle of the file? I'm just grasping
at straws here, but maybe it's somehow messing up line endings (turning
CRLF pairs into just LF), or using some other kind of encoding for
unicode characters?

If you compare the files with cmp, does it say:

$ cmp original truncated
cmp: EOF on truncated

that's what I would expect if it's a strict truncation. If it says
anything else, you've got a data munging problem.

What I would normally do around this time is run a system call trace on
the process to watch all the descriptor related (i.e. open, create,
write) system calls. On OSX, that means dtruss. Unfortunately, I'm
not that familiar with the OSX variant so I can't give you specific
advice about which options to use.

When you can see the system calls, you know exactly what your process is
doing. You should be able to see the output file being opened and a
descriptor returned, then find all the write() calls to that descriptor.
You'll also be able to find any other system calls on that pathname
after the descriptor is closed.

Please report back what you find!

Oh, another trick you might want to try is making the output file path
/dev/stdout and redirecting the output into a file with the shell. See
if that makes any difference. Or, try something like (assuming the -o
option to your script sets the output filename):

python my_prog.py -o /dev/stdout | dd bs=1 of=xxx

That will do a couple of things. First, dd will report how many bytes
it read and wrote, so you can see if that's the correct number. Also,
since your process will no longer be writing to a real file, if anything
is doing something weird like a seek() after you're done writing, that
will fail since you can't seek() on a pipe.

[Terry Jan Reedy]

On 4/12/2013 3:32 AM, Chris Angelico wrote:

> Hold it one moment... You're not actually calling close. The file's
> still open. Is that a copy/paste problem, or is that your actual code?
>
> In Python, a function call ALWAYS has parentheses after it. Evaluating
> a function's name like that returns the function (or method) object,
> which you then do nothing with. (You could assign it someplace, for
> instance, and call it later.) Try adding empty parens:
>
> f.close()
>
> and see if that solves the problem. Alternatively, look into the
> 'with' statement and the block syntax that it can give to I/O
> operations.

I say *definitely* use a 'with' statement. Part of its purpose is to
avoid close bugs.

[Roy Smith]

In article <51674ffc$0$29977$c3e8da3$5496...@news.astraweb.com>,

Steven D'Aprano <steve+comp....@pearwood.info> wrote:

It is *possible* that this is the problem, but it's really way far out
on the long tail of possibilities. If the file system were corrupted or
the disk faulty, the odds are you would be seeing all sorts of other
problems. And this would not be anywhere near as repeatable as the OP
is describing.

Think horses, not zebras.

[Roy Smith]

In article <mailman.510.1365755...@python.org>,

Cameron Simpson <c...@zip.com.au> wrote:

> 45046 is exactly 11 * 4096. I'd say your I/O is using 4KB blocks,
> and the last partial block (to make it up to 47970) didn't get
> written (at the OS level).

Yeah, this sounds like a good diagnosis.

BTW, the dtruss command I recommended in my earlier post would confirm
this. But, to be honest, it's such a likely scenario that it hardly
needs confirmation.

[Roy Smith]

In article <mailman.511.1365758...@python.org>,
Rob Schneider <rms...@gmail.com> wrote:

> f.close

Well, there's your problem. You're not calling close. You forgot the
()'s after the function name!

[88888 Dihedral]

Steven D'Aprano於 2013年4月12日星期五UTC+8上午8時06分21秒寫道：

> On Thu, 11 Apr 2013 19:55:53 +0000, Neil Cerutti wrote:
>
>
>
> > On 2013-04-11, Rob Schneider <rms...@gmail.com> wrote:
>
> >> Thanks. Yes, there is a close function call before the copy is
>
> >> launched. No other writes. Does Python wait for file close command to
>
> >> complete before proceeding?
>
> >
>
> > The close method is defined and flushing and closing a file, so it
>
> > should not return until that's done.
>
>
>
> But note that "done" in this case means "the file system thinks it is
>
> done", not *actually* done. Hard drives, especially the cheaper ones,
>
> lie. They can say the file is written when in fact the data is still in
>
> the hard drive's internal cache and not written to the disk platter.
>
> Also, in my experience, hardware RAID controllers will eat your data, and
>
> then your brains when you try to diagnose the problem.
>
>

Don't you model this as a non-blocking operation in
your program?

>
> I would consider the chance that the disk may be faulty, or the file
>
> system is corrupt. Does the problem go away if you write to a different
>
> file system or a different disk?
>
>
>
>
>
>
>
> --
>
> Steven

Back-ups and read-back verifications are important for
those who care.

[Nobody]

On Fri, 12 Apr 2013 00:06:21 +0000, Steven D'Aprano wrote:

>> The close method is defined and flushing and closing a file, so it
>> should not return until that's done.
>
> But note that "done" in this case means "the file system thinks it is
> done", not *actually* done. Hard drives, especially the cheaper ones,
> lie. They can say the file is written when in fact the data is still in
> the hard drive's internal cache and not written to the disk platter.
> Also, in my experience, hardware RAID controllers will eat your data, and
> then your brains when you try to diagnose the problem.

None of which is likely to be relevant here, as any subsequent access to
the file will reference the in-memory copy; the disk will only get
involved if the data has already been flushed from the OS' cache and has
to be read back in from disk.

write(), close(), etc return once the data has been written to the
OS' disk cache. At that point, the OS usually won't have even started
sending the data to the drive, let alone waited for the drive to report
(or claim) that the data has been written to the physical disk.

If you want to wait for the data written to be written to the physical
disk (in order to obtain specific behaviour with respect to an unclean
shutdown), use f.flush() followed by os.fsync(f.fileno()).

But most of the time, there's no point. If you actually care about what
happens in the event of an unclean shutdown, you typically also need to
sync the directory, otherwise the file's contents will get sync'd but the
file's very existence might not be.

[Chris Angelico]

On Sat, Apr 13, 2013 at 12:33 PM, Nobody <nob...@nowhere.com> wrote:
> But most of the time, there's no point. If you actually care about what
> happens in the event of an unclean shutdown, you typically also need to
> sync the directory, otherwise the file's contents will get sync'd but the
> file's very existence might not be.

Or just store your content in a PostgreSQL database, and let it worry
about all the platform-specific details of how to fsync reliably.

ChrisA

[Steven D'Aprano]

On Sat, 13 Apr 2013 03:33:29 +0100, Nobody wrote:

> On Fri, 12 Apr 2013 00:06:21 +0000, Steven D'Aprano wrote:
>
>>> The close method is defined and flushing and closing a file, so it
>>> should not return until that's done.
>>
>> But note that "done" in this case means "the file system thinks it is
>> done", not *actually* done. Hard drives, especially the cheaper ones,
>> lie. They can say the file is written when in fact the data is still in
>> the hard drive's internal cache and not written to the disk platter.
>> Also, in my experience, hardware RAID controllers will eat your data,
>> and then your brains when you try to diagnose the problem.
>
> None of which is likely to be relevant here,

Since we've actually identified the bug (the OP was using file.close
without actually calling it), that's certainly the case :-)


[...]

> If you want to wait for the data written to be written to the physical
> disk (in order to obtain specific behaviour with respect to an unclean
> shutdown), use f.flush() followed by os.fsync(f.fileno()).

If only it were that simple. It has been documented that some disks will
lie, even when told to sync. When I say "some", I mean *most*. There's
probably nothing you can do about it, apart from not using that model or
brand of disk, so you have to just live with the risk.

http://queue.acm.org/detail.cfm?id=2367378

USB sticks are especially nasty. I've got quite a few USB thumb drives
where the "write" light keeps flickering for anything up to five minutes
after the OS reports that the drive has been unmounted and is safe to
unplug. I corrupted the data on these quite a few times until I noticed
the light. And let's not even mention the drives that have no light at
all...

But my favourite example of lying hard drives of all time is this:

http://blog.jitbit.com/2011/04/chinese-magic-drive.html

I want one of those!



--
Steven

[Chris Angelico]

On Sat, Apr 13, 2013 at 1:17 PM, Steven D'Aprano
<steve+comp....@pearwood.info> wrote:
> On Sat, 13 Apr 2013 03:33:29 +0100, Nobody wrote:
>> If you want to wait for the data written to be written to the physical
>> disk (in order to obtain specific behaviour with respect to an unclean
>> shutdown), use f.flush() followed by os.fsync(f.fileno()).
>
> If only it were that simple. It has been documented that some disks will
> lie, even when told to sync. When I say "some", I mean *most*. There's
> probably nothing you can do about it, apart from not using that model or
> brand of disk, so you have to just live with the risk.

It's often close to that simple. With most hard disks, you can make
them 100% reliable, but you may have to check some disk parameters (on
Linux, that's just a matter of writing to something in /proc
somewhere, don't remember the details but it's easy to check). The
worst offenders I've met are SSDs...

> USB sticks are especially nasty. I've got quite a few USB thumb drives
> where the "write" light keeps flickering for anything up to five minutes
> after the OS reports that the drive has been unmounted and is safe to
> unplug. I corrupted the data on these quite a few times until I noticed
> the light. And let's not even mention the drives that have no light at
> all...

... but you've met worse.

> But my favourite example of lying hard drives of all time is this:
>
> http://blog.jitbit.com/2011/04/chinese-magic-drive.html
>
> I want one of those!

Awesome! It's the new version of DoubleSpace / DriveSpace!

http://en.wikipedia.org/wiki/DriveSpace

(And its problems, according to that Wikipedia article, actually had
the same root cause - write caching that the user wasn't aware of.
Great.)

ChrisA