Locking and MacOS X Finder

classic Classic list List threaded Threaded
2 messages Options
Reply | Threaded
Open this post in threaded view
|

Locking and MacOS X Finder

Michele Mauro
I'm working on an application to expose as WebDAV the contents of our application, and to enable the upload of files via WebDAV. The initial client will be the MacOS X Finder.

I have managed to manage most of its behaviours, from caching locally all the little invisible files to implement the "create empty/delete/create real" cycle so that the real application only gets the real file, and so on. Still, there are frequent and difficoult to understand (for me, at least) errors.

In particular, I was able, in a single session to get three different outcomes from copying three files on a WebDAV folder:
a) the first file was copied fine, but the Finder emitted a "File is busy" error.
b) the second file has been created as empty, i.e. the real bytes were never sent to my application, with another "File is busy" error.
c) the third file copied just fine, with no errors and transferring all the content.

Why three different behaviours in just a couple of minutes, from the same code?

I don't have exceptions in the log; the harsher message I can find is something like this:

22:54:41.198 [qtp1072423397-30] WARN  io.milton.http.HandlerHelper - Locked out. ifHeader=null lock-token header=null, but actual token: 40d69914-d9ac-4eda-8665-5ff55af59153 LockedByUser=
 RequestUser=admin

But all the three files got a similar message, and the outcome doesn't seem related to this.

From what I read in the logs, the message is caused by two different threads competing for the same lock:

22:54:41.052 [qtp1072423397-20] INFO  io.milton.http.HttpManager - LOCK :: http://localhost:8080/brun/._IMG_0018.JPG start
22:54:41.052 [qtp1072423397-20] INFO  it.warda.webdavip.egresources.EgData - roots cache hit
22:54:41.053 [qtp1072423397-20] INFO  i.w.webdavip.egresources.WardaDriver - folder cache hit admin:-1
22:54:41.054 [qtp1072423397-20] INFO  i.w.webdavip.egresources.WardaDriver - fetching folder contents -1 root g/injopt/nodi/ null user admin
22:54:41.055 [qtp1072423397-20] INFO  i.w.webdavip.egresources.WardaDriver - fetching folder 20410 brun null g/injopt/contents/20410/ user admin
22:54:41.055 [qtp1072423397-20] INFO  i.w.webdavip.egresources.WardaDriver - folder children cache hit admin#20410
22:54:41.055 [qtp1072423397-20] INFO  i.w.webdavip.egresources.WardaDriver - folder synth children cache hit admin&20410
22:54:41.055 [qtp1072423397-30] INFO  io.milton.http.HttpManager - LOCK :: http://localhost:8080/brun/._IMG_0018.JPG start
22:54:41.055 [qtp1072423397-30] INFO  it.warda.webdavip.egresources.EgData - roots cache hit
22:54:41.056 [qtp1072423397-20] DEBUG io.milton.http.webdav2.LockHandler - locking existing resource: ._IMG_0018.JPG
22:54:41.056 [qtp1072423397-30] INFO  i.w.webdavip.egresources.WardaDriver - folder cache hit admin:-1
22:54:41.056 [qtp1072423397-20] DEBUG i.m.h.h.a.SecurityManagerBasicAuthHandler - authenticate
22:54:41.057 [qtp1072423397-30] INFO  i.w.webdavip.egresources.WardaDriver - fetching folder contents -1 root g/injopt/nodi/ null user admin
22:54:41.058 [qtp1072423397-30] INFO  i.w.webdavip.egresources.WardaDriver - fetching folder 20410 brun null g/injopt/contents/20410/ user admin
22:54:41.058 [qtp1072423397-30] INFO  i.w.webdavip.egresources.WardaDriver - folder children cache hit admin#20410
22:54:41.059 [qtp1072423397-30] INFO  i.w.webdavip.egresources.WardaDriver - folder synth children cache hit admin&20410
22:54:41.060 [qtp1072423397-30] DEBUG io.milton.http.webdav2.LockHandler - locking existing resource: ._IMG_0018.JPG
22:54:41.060 [qtp1072423397-30] DEBUG i.m.h.h.a.SecurityManagerBasicAuthHandler - authenticate
22:54:41.119 [qtp1072423397-20] INFO  it.warda.webdavip.EgSecurityManager - object authenticate user: admin session f9395f7e5597df13f9cb6dfd0baaa6f9cff63562-username=admin
22:54:41.119 [qtp1072423397-20] DEBUG i.m.h.h.a.SecurityManagerBasicAuthHandler - result: EgPrincipal:http://www.warda.it/user/admin
22:54:41.119 [qtp1072423397-20] DEBUG i.milton.http.annotated.AnnoResource - authorise: ACL cannot be calculated so use security manager: it.warda.webdavip.EgSecurityManager@183be6a7
22:54:41.119 [qtp1072423397-20] INFO  it.warda.webdavip.EgSecurityManager - authorize in request
22:54:41.119 [qtp1072423397-20] DEBUG io.milton.http.LockTimeout - ..requested timeout: Second-600
22:54:41.120 [qtp1072423397-20] DEBUG io.milton.http.LockInfoSaxHandler - LockInfo: <?xml version="1.0" encoding="utf-8"?>
<D:lockinfo xmlns:D="DAV:">
<D:lockscope><D:exclusive/></D:lockscope>
<D:locktype><D:write/></D:locktype>
<D:owner>
</D:owner>
</D:lockinfo>

22:54:41.121 [qtp1072423397-20] DEBUG io.milton.http.webdav2.LockHandler - locking: ._IMG_0018.JPG
22:54:41.122 [qtp1072423397-20] DEBUG io.milton.http.webdav2.LockHandler - ..locked ok: 40d69914-d9ac-4eda-8665-5ff55af59153
22:54:41.122 [qtp1072423397-20] DEBUG io.milton.webdav.utils.LockUtils - appendOwner: false - true
22:54:41.122 [qtp1072423397-20] DEBUG io.milton.webdav.utils.LockUtils - lock response: , <?xml version="1.0" encoding="utf-8" ?>
<d:prop  xmlns:d="DAV:"><d:lockdiscovery><d:activelock><d:locktype><d:write/></d:locktype>
<d:lockscope><d:exclusive/></d:lockscope>
<d:depth>INFINITY</d:depth>
<d:owner>
</d:owner>
<d:timeout>Second-600</d:timeout>
<d:locktoken><d:href>opaquelocktoken:40d69914-d9ac-4eda-8665-5ff55af59153</d:href>
</d:locktoken><d:lockroot><d:href>http://localhost:8080/brun/._IMG_0018.JPG</d:href>
</d:lockroot></d:activelock>
</d:lockdiscovery>
</d:prop>
,
ByteArrayEntity: write: 514 - class org.eclipse.jetty.server.HttpOutput
22:54:41.123 [qtp1072423397-20] INFO  io.milton.http.HttpManager - LOCK :: http://localhost:8080/brun/._IMG_0018.JPG finished 71ms, Status:HTTP/1.1 200 OK, Length:null

As you can see, qtp1072423397-20 started the lock operation on ._IMG_0018.JPG before qtp1072423397-30, and wins. Why two competing threads trying to lock the same resource coming from the same client?

Has anybody found a way to please the Finder and send files over without getting these kind of errors?

Thank you in advance,

Michele Mauro

-- 
Michele Mauro
Chief Technology Officier
Visionest S.r.l. - Process Innovation
Via G.B. Ricci 6/A
35131 Padova - Italy

E-mail: [hidden email]
Mobile: +39 349 2222319
Phone: +39 049 8210229
Fax: +39 049 8774924

_______________________________________________
Milton-users mailing list
[hidden email]
http://lists.justthe.net/mailman/listinfo/milton-users
Reply | Threaded
Open this post in threaded view
|

Re: Locking and MacOS X Finder

bradmacnz
Hi Michele,

I cant say exactly what the problem is, although generally when things go wrong with Finder that often results in locks being left in place which can then cause subsequent operations to fail.

What makes Finder hard to work with is that every user action (eg uploading a file) results in a sequence of several operations. If any one operation fails (where a failure can simply be an unexpected response), the action as a whole fails. BUT the problem is that the sequence doesnt simply stop when one operation failed. So you can just look at the last request to see what went wrong, you need to look at the whole series of requests and find out which one diverged from the normal sequence.

I've recently started pretty much ignoring the lockedByUser that comes with a LOCK request and just using the logged in user as the locking user. This is not strictly correct as per the webdav spec, but it does seem to result in better reliability, particularly with Finder which always sends the meaningless lockedByUser of "http://www.apple.com/webdav_fs/"

I'll see if i can upgrade the SimpleLockManager which is used by default with annotations tomorrow.

Regards,
Brad


On 08/05/14 09:24, Michele Mauro wrote:
I'm working on an application to expose as WebDAV the contents of our application, and to enable the upload of files via WebDAV. The initial client will be the MacOS X Finder.

I have managed to manage most of its behaviours, from caching locally all the little invisible files to implement the "create empty/delete/create real" cycle so that the real application only gets the real file, and so on. Still, there are frequent and difficoult to understand (for me, at least) errors.

In particular, I was able, in a single session to get three different outcomes from copying three files on a WebDAV folder:
a) the first file was copied fine, but the Finder emitted a "File is busy" error.
b) the second file has been created as empty, i.e. the real bytes were never sent to my application, with another "File is busy" error.
c) the third file copied just fine, with no errors and transferring all the content.

Why three different behaviours in just a couple of minutes, from the same code?

I don't have exceptions in the log; the harsher message I can find is something like this:

22:54:41.198 [qtp1072423397-30] WARN  io.milton.http.HandlerHelper - Locked out. ifHeader=null lock-token header=null, but actual token: 40d69914-d9ac-4eda-8665-5ff55af59153 LockedByUser=
 RequestUser=admin

But all the three files got a similar message, and the outcome doesn't seem related to this.

From what I read in the logs, the message is caused by two different threads competing for the same lock:

22:54:41.052 [qtp1072423397-20] INFO  io.milton.http.HttpManager - LOCK :: http://localhost:8080/brun/._IMG_0018.JPG start
22:54:41.052 [qtp1072423397-20] INFO  it.warda.webdavip.egresources.EgData - roots cache hit
22:54:41.053 [qtp1072423397-20] INFO  i.w.webdavip.egresources.WardaDriver - folder cache hit admin:-1
22:54:41.054 [qtp1072423397-20] INFO  i.w.webdavip.egresources.WardaDriver - fetching folder contents -1 root g/injopt/nodi/ null user admin
22:54:41.055 [qtp1072423397-20] INFO  i.w.webdavip.egresources.WardaDriver - fetching folder 20410 brun null g/injopt/contents/20410/ user admin
22:54:41.055 [qtp1072423397-20] INFO  i.w.webdavip.egresources.WardaDriver - folder children cache hit admin#20410
22:54:41.055 [qtp1072423397-20] INFO  i.w.webdavip.egresources.WardaDriver - folder synth children cache hit admin&20410
22:54:41.055 [qtp1072423397-30] INFO  io.milton.http.HttpManager - LOCK :: http://localhost:8080/brun/._IMG_0018.JPG start
22:54:41.055 [qtp1072423397-30] INFO  it.warda.webdavip.egresources.EgData - roots cache hit
22:54:41.056 [qtp1072423397-20] DEBUG io.milton.http.webdav2.LockHandler - locking existing resource: ._IMG_0018.JPG
22:54:41.056 [qtp1072423397-30] INFO  i.w.webdavip.egresources.WardaDriver - folder cache hit admin:-1
22:54:41.056 [qtp1072423397-20] DEBUG i.m.h.h.a.SecurityManagerBasicAuthHandler - authenticate
22:54:41.057 [qtp1072423397-30] INFO  i.w.webdavip.egresources.WardaDriver - fetching folder contents -1 root g/injopt/nodi/ null user admin
22:54:41.058 [qtp1072423397-30] INFO  i.w.webdavip.egresources.WardaDriver - fetching folder 20410 brun null g/injopt/contents/20410/ user admin
22:54:41.058 [qtp1072423397-30] INFO  i.w.webdavip.egresources.WardaDriver - folder children cache hit admin#20410
22:54:41.059 [qtp1072423397-30] INFO  i.w.webdavip.egresources.WardaDriver - folder synth children cache hit admin&20410
22:54:41.060 [qtp1072423397-30] DEBUG io.milton.http.webdav2.LockHandler - locking existing resource: ._IMG_0018.JPG
22:54:41.060 [qtp1072423397-30] DEBUG i.m.h.h.a.SecurityManagerBasicAuthHandler - authenticate
22:54:41.119 [qtp1072423397-20] INFO  it.warda.webdavip.EgSecurityManager - object authenticate user: admin session f9395f7e5597df13f9cb6dfd0baaa6f9cff63562-username=admin
22:54:41.119 [qtp1072423397-20] DEBUG i.m.h.h.a.SecurityManagerBasicAuthHandler - result: EgPrincipal:http://www.warda.it/user/admin
22:54:41.119 [qtp1072423397-20] DEBUG i.milton.http.annotated.AnnoResource - authorise: ACL cannot be calculated so use security manager: it.warda.webdavip.EgSecurityManager@183be6a7
22:54:41.119 [qtp1072423397-20] INFO  it.warda.webdavip.EgSecurityManager - authorize in request
22:54:41.119 [qtp1072423397-20] DEBUG io.milton.http.LockTimeout - ..requested timeout: Second-600
22:54:41.120 [qtp1072423397-20] DEBUG io.milton.http.LockInfoSaxHandler - LockInfo: <?xml version="1.0" encoding="utf-8"?>
<D:lockinfo xmlns:D="DAV:">
<D:lockscope><D:exclusive/></D:lockscope>
<D:locktype><D:write/></D:locktype>
<D:owner>
</D:owner>
</D:lockinfo>

22:54:41.121 [qtp1072423397-20] DEBUG io.milton.http.webdav2.LockHandler - locking: ._IMG_0018.JPG
22:54:41.122 [qtp1072423397-20] DEBUG io.milton.http.webdav2.LockHandler - ..locked ok: 40d69914-d9ac-4eda-8665-5ff55af59153
22:54:41.122 [qtp1072423397-20] DEBUG io.milton.webdav.utils.LockUtils - appendOwner: false - true
22:54:41.122 [qtp1072423397-20] DEBUG io.milton.webdav.utils.LockUtils - lock response: , <?xml version="1.0" encoding="utf-8" ?>
<d:prop  xmlns:d="DAV:"><d:lockdiscovery><d:activelock><d:locktype><d:write/></d:locktype>
<d:lockscope><d:exclusive/></d:lockscope>
<d:depth>INFINITY</d:depth>
<d:owner>
</d:owner>
<d:timeout>Second-600</d:timeout>
<d:locktoken><d:href>opaquelocktoken:40d69914-d9ac-4eda-8665-5ff55af59153</d:href>
</d:locktoken><d:lockroot><d:href>http://localhost:8080/brun/._IMG_0018.JPG</d:href>
</d:lockroot></d:activelock>
</d:lockdiscovery>
</d:prop>
,
ByteArrayEntity: write: 514 - class org.eclipse.jetty.server.HttpOutput
22:54:41.123 [qtp1072423397-20] INFO  io.milton.http.HttpManager - LOCK :: http://localhost:8080/brun/._IMG_0018.JPG finished 71ms, Status:HTTP/1.1 200 OK, Length:null

As you can see, qtp1072423397-20 started the lock operation on ._IMG_0018.JPG before qtp1072423397-30, and wins. Why two competing threads trying to lock the same resource coming from the same client?

Has anybody found a way to please the Finder and send files over without getting these kind of errors?

Thank you in advance,

Michele Mauro

-- 
Michele Mauro
Chief Technology Officier
Visionest S.r.l. - Process Innovation
Via G.B. Ricci 6/A
35131 Padova - Italy

E-mail: [hidden email]
Mobile: +39 349 2222319
Phone: +39 049 8210229
Fax: +39 049 8774924


_______________________________________________
Milton-users mailing list
[hidden email]
http://lists.justthe.net/mailman/listinfo/milton-users


_______________________________________________
Milton-users mailing list
[hidden email]
http://lists.justthe.net/mailman/listinfo/milton-users