search

pimutils / vdirsyncer

📇 Synchronize calendars and contacts.
https://vdirsyncer.pimutils.org/
Other
1.57k stars 163 forks source link

vdirsyncer incorrectly complains that "Storage was completely emptied" #694

Open GSI opened 6 years ago

GSI commented 6 years ago

I successfully synced from local (filesystem on Arch Linux) to remote (radicale server 2.1.8) once. Now on the subsequent runs I get the errer shown below. Note that I am able to sync from the radicale server to a phone. So the remote is not actually empty.

Does it have to do with normalization?

This is vdirsyncer 0.16.3.

debug: Using 1 maximal workers.
Syncing addressbook
debug: PROPFIND http://192.168.1.1:5232/user/addressbook.vcf/
debug: {'User-Agent': 'vdirsyncer/0.16.3', 'Content-Type': 'application/xml; charset=UTF-8', 'Depth': '1'}
debug: <?xml version="1.0" encoding="utf-8" ?>
debug:             <D:propfind xmlns:D="DAV:">
debug:                 <D:prop>
debug:                     <D:resourcetype/>
debug:                     <D:getcontenttype/>
debug:                     <D:getetag/>
debug:                 </D:prop>
debug:             </D:propfind>
debug:             
debug: Sending request...
debug: 207
debug: {'Date': 'Fri, 22 Dec 2017 21:01:02 GMT', 'Server': 'WSGIServer/0.2 CPython/3.6.3', 'DAV': '1, 2, 3, calendar-access, addressbook, extended-mkcol', 'Content-Type': 'text/xml; charset=utf-8', 'Content-Encoding': 'gzip', 'Content-Length': '31299'}
debug: <?xml version='1.0' encoding='utf-8'?>
debug: <multistatus xmlns="DAV:"
xmlns:CR="urn:ietf:params:xml:ns:carddav">
  <response>
    <href>/user/addressbook.vcf/</href>
    <propstat>
      <prop>
        <resourcetype>
          <collection />
        </resourcetype>
      </prop>
      <status>HTTP/1.1 200 OK</status>
    </propstat>
    <propstat>
      <prop>
        <getcontenttype />
        <getetag />
      </prop>
      <status>HTTP/1.1 404 Not Found</status>
    </propstat>
  </response>
  <response>
    <href>
    /user/addressbook.vcf/i1y36nwmmjny43q371o12933nj52x9wg9clw.vcf/</href>
    <propstat>
      <prop>
        <resourcetype>
          <CR:addressbook />
          <collection />
        </resourcetype>
        <getcontenttype>text/vcard</getcontenttype>
        <getetag>"ebf1610a8cd56d4ce5b6aec03d090f23"</getetag>
      </prop>
      <status>HTTP/1.1 200 OK</status>
    </propstat>
  </response>
  <response>
    <href>
    /user/addressbook.vcf/i6g5lzucj5umfdikxgulldltt78wumrwntby.vcf/</href>
    <propstat>
      <prop>
        <resourcetype>
          <CR:addressbook />
          <collection />
        </resourcetype>
        <getcontenttype>text/vcard</getcontenttype>
        <getetag>"9fc7b2fe0990fceb031f6568b04219dd"</getetag>
      </prop>
      <status>HTTP/1.1 200 OK</status>
    </propstat>
  </response>

Many more responses like this before "multistatus" is closed:

</multistatus>

Then loads of messages like this:

debug: Already normalized: '/user/addressbook.vcf/n4vq5kmkwk.vcf/'
debug: Skipping '/user/addressbook.vcf/n4vq5kmkwk.vcf/', is collection.

Finally:

error: addressbook: Storage "addressbook_remote" was completely emptied. If you want to delete ALL entries on BOTH sides, then use `vdirsyncer sync --force-delete addressbook`. Otherwise delete the files for addressbook in your status directory.
error: 1 out of 2 tasks failed.
untitaker commented 6 years ago

Please include slightly more from the debug output.

On Fri, Dec 22, 2017 at 09:11:04PM +0000, GSI wrote:

I successfully synced from local (filesystem on Arch Linux) to remote (radicale server 2.1.8) once. Now on the subsequent runs I get the errer shown below. Note that I am able to sync from the radicale server to a phone. So the remote is not actually empty.

Does it have to do with normalization?

This is vdirsyncer 0.16.3.

debug: Using 1 maximal workers.
Syncing addressbook
debug: PROPFIND http://192.168.1.1:5232/user/addressbook.vcf/
debug: {'User-Agent': 'vdirsyncer/0.16.3', 'Content-Type': 'application/xml; charset=UTF-8', 'Depth': '1'}
debug: <?xml version="1.0" encoding="utf-8" ?>
debug:             <D:propfind xmlns:D="DAV:">
debug:                 <D:prop>
debug:                     <D:resourcetype/>
debug:                     <D:getcontenttype/>
debug:                     <D:getetag/>
debug:                 </D:prop>
debug:             </D:propfind>
debug:             
debug: Sending request...
debug: 207
debug: {'Date': 'Fri, 22 Dec 2017 21:01:02 GMT', 'Server': 'WSGIServer/0.2 CPython/3.6.3', 'DAV': '1, 2, 3, calendar-access, addressbook, extended-mkcol', 'Content-Type': 'text/xml; charset=utf-8', 'Content-Encoding': 'gzip', 'Content-Length': '31299'}
debug: <?xml version='1.0' encoding='utf-8'?>
debug: <multistatus xmlns="DAV:" xmlns:CR="urn:ietf:params:xml:ns:carddav"><response><href>/user/addressbook.vcf/</href><pr

(a lot of stuff here, then loads of messages like this:)

debug: Already normalized: '/user/addressbook.vcf/n4vq5kmkwk.vcf/'
debug: Skipping '/user/addressbook.vcf/n4vq5kmkwk.vcf/', is collection.
error: addressbook: Storage "addressbook_remote" was completely emptied. If you want to delete ALL entries on BOTH sides, then use `vdirsyncer sync --force-delete addressbook`. Otherwise delete the files for addressbook in your status directory.
error: 1 out of 2 tasks failed.

-- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/pimutils/vdirsyncer/issues/694

GSI commented 6 years ago

I added some of the XML responses. That's pretty much all that was missing from the client side logs.

On the server side, all looks good to. Apparently all contacts are offered correctly.

Starting with:

[8055a8e00] INFO: PROPFIND request for '/user/addressbook.vcf/' with depth '1' received from 192.168.1.6 using 'vdirsyncer/0.16.3'

Then after confirming successful login and such:

[8055a8e00] DEBUG: 'user' has read and write access to collection 'user/addressbook.vcf'
[8055a8e00] DEBUG: 'user' has read and write access to collection 'user/addressbook.vcf/i1y36nwmmjny43q371o12933nj52x9wg9clw.vcf'

Then successful responses:

<response>
        <href>/user/addressbook.vcf/dng5jn1ogv.vcf/</href>
        <propstat>
                <prop>
                        <resourcetype>
                                <CR:addressbook />
                                <collection />
                        </resourcetype> 
                        <getcontenttype>text/vcard</getcontenttype> 
                        <getetag>"6a46b50da4e3d19a1ce76620594f866d"</getetag> 
                </prop> 
                <status>HTTP/1.1 200 OK</status>
        </propstat> 
</response>

Ending with:

[8055a8900] INFO: PROPFIND response status for '/user/addressbook.vcf/' with depth '1' in 6.355 seconds: 207 Multi-Status
untitaker commented 6 years ago

It seems that your server response is not valid. Radicale advertises each contact as addressbook. Sorry, I cant help here.

GSI commented 6 years ago

Interesting. I'll reference this from a radicale issue then.

untitaker commented 6 years ago

Could you check whether you have an actual folder like this: /user/addressbook.vcf/dng5jn1ogv.vcf/

GSI commented 6 years ago

Sure. Here it is:

# ls -al dng5jn1ogv.vcf/
total 229
drwxr-xr-x    3 radicale  radicale     5 Dec 20 20:16 .
drwxr-xr-x  681 radicale  radicale   681 Dec 20 22:35 ..
drwxr-xr-x    5 radicale  radicale     5 Dec 22 05:16 .Radicale.cache
-rw-------    1 radicale  radicale    23 Dec 20 20:16 .Radicale.props
-rw-------    1 radicale  radicale  4754 Dec 20 20:16 f829b22a-3764-5beb-a652-9cf89e866f5d.vcf

I remember that Radicale v1 used a different structure.

untitaker commented 6 years ago

Is that directory representing an addressbook, or do you have one such folder for each contact?

GSI commented 6 years ago

addressbook.vcf is the folder that reperesents the addressbook.

Then, there is one subdirectory per contact. The subdirectory name (dng5jn1ogv.vcf in this example) equals the file name on my local machine as initially synced (by vdirsyncer) to Radicale.

On the server side, the file f829b22a-3764-5beb-a652-9cf89e866f5d.vcf holds the actual contact data.

untitaker commented 6 years ago

this seems incredibly wrong. Did vdirsyncer upload the data like that, or another client?

GSI commented 6 years ago

vdirsyncer did.

It may appear wrong, but I think it's just how the Radicale team decided to manage things in v2.

untitaker commented 6 years ago

Ok, please try this:

1.) Wipe radicale 2.) Delete vdirsyncer status 3.) vdirsyncer sync with debug output

IOW, I need logs of vdirsyncer uploading stuff

GSI commented 6 years ago

Ok. Here's the output from the initial discover step:

debug: Using 1 maximal workers.
Discovering collections for pair addressbook
addressbook_local:
debug: PROPFIND http://192.168.1.8:5232/user/addressbook.vcf/
debug: {'User-Agent': 'vdirsyncer/0.16.3', 'Content-Type': 'application/xml; charset=UTF-8', 'Depth': '1'}
debug: 
debug:     <d:propfind xmlns:d="DAV:">
debug:         <d:prop>
debug:             <d:resourcetype />
debug:         </d:prop>
debug:     </d:propfind>
debug:     
debug: Sending request...
debug: 207
debug: {'Date': 'Mon, 25 Dec 2017 21:30:16 GMT', 'Server': 'WSGIServer/0.2 CPython/3.6.3', 'DAV': '1, 2, 3, calendar-access, addressbook, extended-mkcol', 'Content-Type': 'text/xml; charset=utf-8', 'Content-Encoding': 'gzip', 'Content-Length': '185'}
debug: <?xml version='1.0' encoding='utf-8'?>
debug: <multistatus xmlns="DAV:"><response><href>/user/addressbook.vcf/</href><propstat><prop><resourcetype><collection /></resourcetype></prop><status>HTTP/1.1 200 OK</status></propstat></response></multistatus>
debug: Skipping, not of resource type {urn:ietf:params:xml:ns:carddav}addressbook: <Element '{DAV:}response' at 0x7f298e73c7c8>
debug: Given URL is not a homeset URL
debug: PROPFIND http://192.168.1.8:5232/user/addressbook.vcf/
debug: {'User-Agent': 'vdirsyncer/0.16.3', 'Content-Type': 'application/xml; charset=UTF-8', 'Depth': '0'}
debug: 
debug:         <d:propfind xmlns:d="DAV:">
debug:             <d:prop>
debug:                 <d:current-user-principal />
debug:             </d:prop>
debug:         </d:propfind>
debug:         
debug: Sending request...
debug: 207
debug: {'Date': 'Mon, 25 Dec 2017 21:30:18 GMT', 'Server': 'WSGIServer/0.2 CPython/3.6.3', 'DAV': '1, 2, 3, calendar-access, addressbook, extended-mkcol', 'Content-Type': 'text/xml; charset=utf-8', 'Content-Encoding': 'gzip', 'Content-Length': '189'}
debug: <?xml version='1.0' encoding='utf-8'?>
debug: <multistatus xmlns="DAV:"><response><href>/user/addressbook.vcf/</href><propstat><prop><current-user-principal><href>/user/</href></current-user-principal></prop><status>HTTP/1.1 200 OK</status></propstat></response></multistatus>
debug: PROPFIND http://192.168.1.8:5232/user/
debug: {'User-Agent': 'vdirsyncer/0.16.3', 'Content-Type': 'application/xml; charset=UTF-8', 'Depth': '0'}
debug: 
debug:     <d:propfind xmlns:d="DAV:" xmlns:c="urn:ietf:params:xml:ns:carddav">
debug:         <d:prop>
debug:             <c:addressbook-home-set />
debug:         </d:prop>
debug:     </d:propfind>
debug:     
debug: Sending request...
debug: 207
debug: {'Date': 'Mon, 25 Dec 2017 21:30:21 GMT', 'Server': 'WSGIServer/0.2 CPython/3.6.3', 'DAV': '1, 2, 3, calendar-access, addressbook, extended-mkcol', 'Content-Type': 'text/xml; charset=utf-8', 'Content-Encoding': 'gzip', 'Content-Length': '203'}
debug: <?xml version='1.0' encoding='utf-8'?>
debug: <multistatus xmlns="DAV:" xmlns:CR="urn:ietf:params:xml:ns:carddav"><response><href>/user/</href><propstat><prop><CR:addressbook-home-set><href>/user/</href></CR:addressbook-home-set></prop><status>HTTP/1.1 200 OK</status></propstat></response></multistatus>
debug: PROPFIND http://192.168.1.8:5232/user/
debug: {'User-Agent': 'vdirsyncer/0.16.3', 'Content-Type': 'application/xml; charset=UTF-8', 'Depth': '1'}
debug: 
debug:     <d:propfind xmlns:d="DAV:">
debug:         <d:prop>
debug:             <d:resourcetype />
debug:         </d:prop>
debug:     </d:propfind>
debug:     
debug: Sending request...
debug: 207
debug: {'Date': 'Mon, 25 Dec 2017 21:30:23 GMT', 'Server': 'WSGIServer/0.2 CPython/3.6.3', 'DAV': '1, 2, 3, calendar-access, addressbook, extended-mkcol', 'Content-Type': 'text/xml; charset=utf-8', 'Content-Encoding': 'gzip', 'Content-Length': '202'}
debug: <?xml version='1.0' encoding='utf-8'?>
debug: <multistatus xmlns="DAV:"><response><href>/user/</href><propstat><prop><resourcetype><principal /><collection /></resourcetype></prop><status>HTTP/1.1 200 OK</status></propstat></response><response><href>/user/addressbook.vcf/</href><propstat><prop><resourcetype><collection /></resourcetype></prop><status>HTTP/1.1 200 OK</status></propstat></response></multistatus>
debug: Skipping, not of resource type {urn:ietf:params:xml:ns:carddav}addressbook: <Element '{DAV:}response' at 0x7f298e73c8b8>
debug: Skipping, not of resource type {urn:ietf:params:xml:ns:carddav}addressbook: <Element '{DAV:}response' at 0x7f298e73ccc8>
addressbook_remote:
Saved for addressbook: collections = null
GSI commented 6 years ago

sync is currently running. This is how it looks at the beginning:

debug: Using 1 maximal workers.
Syncing addressbook
debug: PROPFIND http://192.168.1.8:5232/user/addressbook.vcf/
debug: {'User-Agent': 'vdirsyncer/0.16.3', 'Content-Type': 'application/xml; charset=UTF-8', 'Depth': '1'}
debug: <?xml version="1.0" encoding="utf-8" ?>
debug:             <D:propfind xmlns:D="DAV:">
debug:                 <D:prop>
debug:                     <D:resourcetype/>
debug:                     <D:getcontenttype/>
debug:                     <D:getetag/>
debug:                 </D:prop>
debug:             </D:propfind>
debug:             
debug: Sending request...
debug: 207
debug: {'Date': 'Mon, 25 Dec 2017 21:34:02 GMT', 'Server': 'WSGIServer/0.2 CPython/3.6.3', 'DAV': '1, 2, 3, calendar-access, addressbook, extended-mkcol', 'Content-Type': 'text/xml; charset=utf-8', 'Content-Encoding': 'gzip', 'Content-Length': '219'}
debug: <?xml version='1.0' encoding='utf-8'?>
debug: <multistatus xmlns="DAV:"><response><href>/user/addressbook.vcf/</href><propstat><prop><resourcetype><collection /></resourcetype></prop><status>HTTP/1.1 200 OK</status></propstat><propstat><prop><getcontenttype /><getetag /></prop><status>HTTP/1.1 404 Not Found</status></propstat></response></multistatus>
debug: Already normalized: '/user/addressbook.vcf/'
debug: Skipping '/user/addressbook.vcf/', is collection.
Copying (uploading) item 008ddadb-29ad-4b92-8f3a-2d8663ae1acc to addressbook_remote
debug: Normalized URL from '008ddadb-29ad-4b92-8f3a-2d8663ae1acc.vcf' to '/user/addressbook.vcf/008ddadb-29ad-4b92-8f3a-2d8663ae1acc.vcf'
debug: PUT http://192.168.1.8:5232/user/addressbook.vcf/008ddadb-29ad-4b92-8f3a-2d8663ae1acc.vcf
debug: {'User-Agent': 'vdirsyncer/0.16.3', 'Content-Type': 'text/vcard', 'If-None-Match': '*'}
debug: BEGIN:VCARD

(sensitive info here)

debug: END:VCARD
debug: Sending request...
debug: 201
debug: {'Date': 'Mon, 25 Dec 2017 21:34:04 GMT', 'Server': 'WSGIServer/0.2 CPython/3.6.3', 'ETag': '"489f603ecd1a7e66e3a6db9078921eef"', 'Content-Length': '0'}

debug: Normalized URL from 'http://192.168.1.8:5232/user/addressbook.vcf/008ddadb-29ad-4b92-8f3a-2d8663ae1acc.vcf' to '/user/addressbook.vcf/008ddadb-29ad-4b92-8f3a-2d8663ae1acc.vcf'
Copying (uploading) item 045p08hkly to addressbook_remote
debug: Normalized URL from '045p08hkly.vcf' to '/user/addressbook.vcf/045p08hkly.vcf'
debug: PUT http://192.168.1.8:5232/user/addressbook.vcf/045p08hkly.vcf
debug: {'User-Agent': 'vdirsyncer/0.16.3', 'Content-Type': 'text/vcard', 'If-None-Match': '*'}
debug: BEGIN:VCARD

(and so forth ...)