"access is denied" while branching

[Gordon Tyler]

I get the above error message when branching from LP into a shared repository. The shared repository already has branches related to the branch that I'm getting from LP. In this case, it's bzr-explorer and I'm branching lp:~simon-kersey/bzr-explorer/565083-fix into my local shared repository, which already has trunk and some feature branches. bzr.log snippet is attached.

Bazaar (bzr) 2.1.1
  Python interpreter: C:\Program Files (x86)\Bazaar\python25.dll 2.5.4
  Python standard library: C:\Program Files (x86)\Bazaar\lib\library.zip
  Platform: Windows-Vista-6.1.7600
  bzrlib: C:\Program Files (x86)\Bazaar\lib\library.zip\bzrlib
  Bazaar configuration: C:\Users\Owner\AppData\Roaming\bazaar\2.0
  Bazaar log file: C:\Users\Owner\Documents\.bzr.log

16.826 Traceback (most recent call last):
  File "bzrlib\commands.pyo", line 853, in exception_to_return_code
  File "bzrlib\commands.pyo", line 1055, in run_bzr
  File "bzrlib\commands.pyo", line 661, in run_argv_aliases
  File "bzrlib\commands.pyo", line 665, in run_direct
  File "bzrlib\cleanup.pyo", line 122, in run_simple
  File "bzrlib\cleanup.pyo", line 156, in _do_with_cleanups
  File "C:/Users/Owner/AppData/Roaming/bazaar/2.0/plugins\qbzr\lib\commands.py", line 788, in run
  File "C:/Users/Owner/AppData/Roaming/bazaar/2.0/plugins\qbzr\lib\subprocess.py", line 789, in run_subprocess_command
  File "bzrlib\commands.pyo", line 1055, in run_bzr
  File "bzrlib\commands.pyo", line 661, in run_argv_aliases
  File "bzrlib\commands.pyo", line 665, in run_direct
  File "bzrlib\cleanup.pyo", line 122, in run_simple
  File "bzrlib\cleanup.pyo", line 156, in _do_with_cleanups
  File "bzrlib\builtins.pyo", line 1232, in run
  File "bzrlib\bzrdir.pyo", line 1201, in sprout
  File "bzrlib\bzrdir.pyo", line 1616, in create_workingtree
  File "bzrlib\workingtree_4.pyo", line 1462, in initialize
  File "bzrlib\transform.pyo", line 2253, in build_tree
  File "bzrlib\transform.pyo", line 2363, in _build_tree
  File "bzrlib\transform.pyo", line 1539, in apply
  File "bzrlib\transform.pyo", line 1667, in _apply_insertions
  File "bzrlib\transform.pyo", line 2902, in rename
WindowsError: [Error 5] Access is denied

qbzr 0.18.5
    QBzr - Qt-based frontend for Bazaar

[Gordon Tyler (doxxx)]

It fails whether I do this from bzr-explorer or from the command-line. Branching the already existing trunk to a new branch in the same shared repository works without error. After doing that, I can merge from the lp branch into the local branch I just created.

[Andrew Bennetts (spiv)]

I wonder what the details of the failing rename operation are (i.e. source and destination names).

Do you have an antivirus program enabled? I'm wondering if perhaps it is holding a temporary file open at just the wrong time, thus preventing bzr from renaming it into its final location.

[Gordon Tyler (doxxx)]

I use the free Microsoft Security Essentials AV. This happened twice,
the second time while I was testing it a few minutes later while
writing this bug report. So I think that rules out locking by AV.

[Pat Tressel (ptressel)]

I get the same error when branching into a new, non-shared repository. This is on WinXP, yes I have a virus checker (McAfee VirusScan), no it wasn't running a scan. However, there was a firewall event at just about the time that bzr branch quit. The firewall log says bazaar.launchpad.net was trying to connect to TCP port 1346, a port it says is commonly used by Alta Analytics License Manager. There's no hint that access was denied, however.

The traceback in my .bzr.log is shorter -- it's below. Note how it essentially got done with branching -- the error happened 46 minutes into the command.

I'll go ask the McAfee folks if the fact that they logged an event means it was blocked. Is :Launchpad using Alta Analytics License Manager? Or something else that might want to use TCP port 1346?

Thanks!

Tue 2010-06-01 08:12:18 -0700
0.140 bazaar version: 2.1.0
0.140 bzr arguments: [u'branch', u'lp:sahana-agasti', u'agasti']
0.172 looking for plugins in C:/Documents and Settings/Patricia Tressel/Application Data/bazaar/2.0/plugins
0.172 looking for plugins in C:/Program Files/Bazaar/plugins
0.406 encoding stdout as sys.stdout encoding 'cp437'
4.828 bzr-svn: using Subversion 1.6.6 ()
15.781 creating repository in file:///C:/Documents%20and%20Settings/Patricia%20Tressel/My%20Documents/sahana/agasti/agasti/.bzr/.
15.969 Using fetch logic to copy between RemoteRepository(bzr+ssh://bazaar.launchpad.net/~sahanaphp-committers/sahana-agasti/1.0/.bzr/)(<RemoteRepositoryFormat>) and CHKInventoryRepository('file:///C:/Documents%20and%20Settings/Patricia%20Tressel/My%20Documents/sahana/agasti/agasti/.bzr/repository/')(<RepositoryFormat2a>)
2736.547 creating branch <bzrlib.branch.BzrBranchFormat7 object at 0x01682AF0> in file:///C:/Documents%20and%20Settings/Patricia%20Tressel/My%20Documents/sahana/agasti/agasti/.bzr/
2738.062 created new branch BzrBranch7('file:///C:/Documents%20and%20Settings/Patricia%20Tressel/My%20Documents/sahana/agasti/agasti/')
2738.250 opening working tree 'C:/Documents and Settings/Patricia Tressel/My Documents/sahana/agasti/agasti'
2768.625 Traceback (most recent call last):
  File "bzrlib\commands.pyo", line 853, in exception_to_return_code
  File "bzrlib\commands.pyo", line 1055, in run_bzr
  File "bzrlib\commands.pyo", line 661, in run_argv_aliases
  File "bzrlib\commands.pyo", line 665, in run_direct
  File "bzrlib\cleanup.pyo", line 122, in run_simple
  File "bzrlib\cleanup.pyo", line 156, in _do_with_cleanups
  File "bzrlib\builtins.pyo", line 1232, in run
  File "bzrlib\bzrdir.pyo", line 1201, in sprout
  File "bzrlib\bzrdir.pyo", line 1616, in create_workingtree
  File "bzrlib\workingtree_4.pyo", line 1462, in initialize
  File "bzrlib\transform.pyo", line 2253, in build_tree
  File "bzrlib\transform.pyo", line 2363, in _build_tree
  File "bzrlib\transform.pyo", line 1539, in apply
  File "bzrlib\transform.pyo", line 1667, in _apply_insertions
  File "bzrlib\transform.pyo", line 2902, in rename
WindowsError: [Error 5] Access is denied

2768.625 Transferred: 77568KiB (28.1K/s r:77567K w:1K)
2768.625 return code 3

[Robert Collins (lifeless)]

The virus scanner is the most likely culprit - many virus scanners
implicitly lock the file they are scanning, and bzr tries to rename
the file while its locked, which fails.

If you could try doing a branch with the scanner actually disabled,
(turn 'on-demand' or 'on-access' scanning off), I suspect it will
work. If that works, file a bug with mcafee :)

We might be able to work around it, but its going to be ugly.

[Pat Tressel (ptressel)]

It's not running a scan -- that was a firewall access. I know for sure it wasn't running a scan or trying to prevent file access because it had already done its weekly scan the day before, and the file access was by my account running a local command on a file in my own directory. The particular version of virus checker I have does not check file accesses at all, let alone to user files -- if a virus checker does watch file accesses, it's usually only system files they watch.

Do you know what might be trying to connect to TCP port 1346? Is there a license manager in use?

[Pat Tressel (ptressel)]

Alta Analytics is the US and European distributor for NetMap Analytics, and Australian company providing insurance and fraud detection services: http://www.netmap.com.au/

Perhaps they registered that port once upon a time, but it's no longer in use by them, and <something else> is borrowing it... A web search for Alta Analytics License Manager doesn't turn up the company -- it just finds references to that port number. There's no site search on the NetMap site, or I'd search for "license manager" there. A Google search for "license manager site:netmap.com.au" gets no results.

Has launchpad been hacked?

[Pat Tressel (ptressel)]

Should add, I've successfully branched other from other lp branches recently -- May 15. Same AV running. (That branch was into a directory that had a shared repository. Not sure that was used, though, because the branch created a new .bzr inside the target directory, and the date on the shared repository didn't change. If, for some unknown reason, it didn't use the shared repository, then it was making a new repository, as was the command on which I got the error.)

[Andrew Bennetts (spiv)]

Pat Tressel wrote:
> I get the same error when branching into a new, non-shared repository.
> This is on WinXP, yes I have a virus checker (McAfee VirusScan), no it
> wasn't running a scan. However, there was a firewall event at just
> about the time that bzr branch quit. The firewall log says
> bazaar.launchpad.net was trying to connect to TCP port 1346, a port it
> says is commonly used by Alta Analytics License Manager. There's no
> hint that access was denied, however.

bazaar.launchpad.net does not ever try to connect to you. I believe 1346 is in
Windows' ephemeral port range, so it was probably the local port number
allocated when your system connected to bazaar.launchpad.net. The warning is
likely due to your system receiving a packet just after it closed the connection
on its side. It's pretty common that one side closes the connection by
effectively sending a "I'm going to close the connection" message followed by
actually sending the "connection is closed" message... and it is common for the
other side to send a reply acknowledging the first message before it has
received the second.

In short, that seems quite normal. I think the firewall warning is a red
herring here, both because a) that event seems normal, and b) the network part
of bzr is working just fine for you, it's renaming a file on your disk that is
failing.

[Andrew Bennetts (spiv)]

Pat Tressel wrote:
[...]
> The particular version of virus checker I have does not check file
> accesses at all, let alone to user files -- if a virus checker does
> watch file accesses, it's usually only system files they watch.

Does it check newly created files, though? It's pretty common for virus
checkers to do that so that they can catch viruses in downloads before
you try to use the download.

[Robert Collins (lifeless)]

You said you use mcafee, which at least in the past definitely
accessed files all over the place, on-demand.

Not saying that its definitely that, but we've had things looking just
like this bug reported many times with a windows virus scanner as the
immediate-cause of the problem.

[Pat Tressel (ptressel)]

I'm not running McAfee SystemGuard. If McAfee checking new files were the problem, why doesn't this happen on other new files? Never seen it outside of this case. I don't see why McAfee would deny the rename -- it wouldn't be different from me doing a rename on the file using the Windows command line.

Could "access denied" be due to the file being locked? Is bazaar running multiple threads? And are multiple threads trying to access that file? That's the only way I can think of that there would be contention. Otherwise, any file check would be synchronous -- all it would do is delay the file access.

[Andrew Bennetts (spiv)]

Pat Tressel wrote:
[...]
> Has launchpad been hacked?

On the evidence so far: no. See my earlier response. If you're still
concerned open a separate bug or question about it, as it is unrelated
to the “access is denied” issue that this bug report is about.

[Robert Collins (lifeless)]

Sorry, you did say 'Microsoft Security Essentials AV' and I read mcafee.

[Robert Collins (lifeless)]

Ok, I've just done some reading on MS Essentials AV, and it looks like
what it does is this:

when a file is written, it hooks into the close, then reads the file
itself, and if its a virus, quarantines it.

So when bzr closes a large pack file, there will be a potentially
significant period while MS EAV is reading that file, and bzr is
simultaneously trying to rename it. And it does seem that this is a
slow thing - there are reports of users being able to *open* infected
zips before MS EAV scans them [which is, uhm, undesirable :)].

I repeat, could you *please* disable the real time scan facility in MS
EAV and try again. If it is an interaction with MS EAV we can look at
how to work around it (but really, its buggy, not even using the
filter drive approach other virus scanners have used for years to
avoid race conditions - like this one - permitting viruses to
execute).

-Rob

[Andrew Bennetts (spiv)]

Pat Tressel wrote:
> Should add, I've successfully branched other from other lp branches
> recently -- May 15. Same AV running. (That branch was into a directory

Note that if the problem is your AV scanning files as they are created,
then the problem is likely to be very timing sensitive, so the fact that
other branch operations worked in the presence of your AV doesn't rule
out your AV being involved in this issue. Sadly if it is timing
sensitive then it may also be hard to definitely say when it is fixed :/

If it is timing sensitive, I wonder if the size of the tree or
individual files makes this more or less likely? I see that tree has a
couple of files over 1M, including one that is 1.9M.

[Robert Collins (lifeless)]

I'd expect large branches - which write large pack files - to trigger
more often.

[Martin Pool (mbp)]

> The firewall log says bazaar.launchpad.net was trying to connect to TCP port 1346, a port it says is commonly used by Alta Analytics License Manager. There's no hint that access was denied, however.

I suspect that 1346 is actually the local transient/ephemeral port, and this was your machine trying to connect from local port 1346 to bazaar.launchpad.net (port 80 or 22 or 443), and your firewall is a bit confused.

http://en.wikipedia.org/wiki/Ephemeral_port says that Windows "through server 2003" use TCP ports 1025-5000 as ephemeral ports, and I presume that would include XP.

[Pat Tressel (ptressel)]

Ok, I've turned off McAfee on-access scan and am retrying the branch. This will take about 50 minutes... (It appears I now have a version of McAfee with on-access scan -- didn't a month ago AFAIK, and full scans took > 10 hours. But it reinstalled itself a month ago when my subscription renewed.) This won't tell you anything about MS EAV. And I'll have to try it again afterward with on-access scan turned on.

[Andrew Bennetts (spiv)]

Robert Collins wrote:
[...]
> So when bzr closes a large pack file, there will be a potentially

A minor correction: note that Pat's error occurs during build_tree
rather in the pack code:

"""
  File "bzrlib\bzrdir.pyo", line 1616, in create_workingtree
  File "bzrlib\workingtree_4.pyo", line 1462, in initialize
  File "bzrlib\transform.pyo", line 2253, in build_tree
  File "bzrlib\transform.pyo", line 2363, in _build_tree
  File "bzrlib\transform.pyo", line 1539, in apply
  File "bzrlib\transform.pyo", line 1667, in _apply_insertions
  File "bzrlib\transform.pyo", line 2902, in rename
"""

[...]
> I repeat, could you *please* disable the real time scan facility in MS
> EAV and try again. If it is an interaction with MS EAV we can look at
[...]

This advice still applies, though.

[Pat Tressel (ptressel)]

No joy at distinguishing with and without on-access scan running -- this time it worked both ways.

[Pat Tressel (ptressel)]

Re. the size of the tree -- the one I'm branching is lp:sahana-agasti.

[DamonOverboe (lp-20-dto1)]

At work we use Norton and Microsoft Security Essentials, and I was seeing this randomly with larger repositories. Mine take a minute though, not fifty.

I've worked around it by going into MSE and ignoring my source directory. Go to Settings: Excluded Files & Locations

So far, this has worked around it.