[Freedombox-discuss] Tracking down the radicale problem.

Mon Apr 1 21:51:46 BST 2019

On Mon, Apr 01, 2019 at 02:20:48AM +0200, Jonas Smedegaard wrote:
> Quoting A. F. Cano (2019-04-01 00:11:58)
> > On Wed, Mar 27, 2019 at 08:46:52AM +0100, Jonas Smedegaard wrote:
> > > If you have configured Radicale to run with uWSGI (only, not also 

ps aux | grep radicale only shows the uwsgi processes, so that part
should be ok.

> > > itself listen on same port!) then you should first check the Apache2 
> > > logs if it received the requests you expect it to.  And then check 
> > > uWSGI logs if it received the requests Apache2 was configured to 
> > > proxy.

Nothing shows up in the apache2 logs when I "fetch" while creating a
DAV groupware calendar.  Instead a get the HTTP error (0).  This is
with Korganizer on the same machine as the radicale server, Debian
testing.

> > 
> > The uwsgi logs only show the staring of the processes:
> > 
> > Sun Mar 31 14:19:05 2019 - spawned uWSGI master process (pid: 945)
> > Sun Mar 31 14:19:05 2019 - spawned uWSGI worker 1 (pid: 1390, cores: 4)
> > Sun Mar 31 14:19:05 2019 - spawned uWSGI worker 2 (pid: 1391, cores: 4)
> > Sun Mar 31 14:19:05 2019 - spawned uWSGI worker 3 (pid: 1392, cores: 4)
> 
> Besides the chatter for start and stop of uwsgi daemon itself, It should 
> have an entry corresponding with each entry in Apache access log.

Nothing shows up here either.

> > [ about the $(DOMAIN) issue ]
> > 
> > I went looking further and found
> > 
> > https://radicale.org/1to2/
> > 
> > Per that page installed radicale 1.1
> > 
> > dpkg -i python-radicale_1.1.6-4_all.deb
> 
> You should downgrade the "radicale" package too, to get the commandline 
> application.

Duh! Of course.  I overlooked that package.  After I installed it I
could run the --export-storage command and it completed without error,
after I had created a new empty directory.  I now have, under
/var/lib/radicale/collections/<user>/,
new directories called calendar.ics and addressbook.vcf under which are
many other files that used to be in one file with each name in the older
version.  I copied those directories (tar & ftp) to the FreedomBox, so
now I have identical data in the test machine and the FreedomBox.

But I get different errors.  In the test machine nothing shows up in the
apache2 or uwsgi log files.  I only get that HTTP error (0) and no data
in the radicale instance installed there shows up in Korganizer or
Kaddressbook.  I suspect this is some authentication issue.  In the test
machine I use the user name and password with which I log in.  In the
FreedomBox it's the admin user.

In the FreedomBox, which used to work, I get errors from any machine I
attempt to connect from: the testing machine which runs Debian testing,
another one that runs Debian stable (and used to work as configured) and
the android phone with DAVdroid (that also used to work as configured).
Even after restarting radicale, I get these messages.

These are the latest tests, after converting the data to v2.x format.
Some of the errors are the previously discussed "can't compare
offset-naive and offset-aware datetimes", but should these errors be
so fatal that they make the whole sync procedure fail? Is the only way
to fix this to go calendar event by calendar event and manually correct
these dates or delete the item?  And then there's the 'VCARD components
must contain at least 1 FN'  Is there some "lint"-like tool to clean up
all those entries?

>From the phone.  Manual sync.

[7fda9bf1b700] ERROR: An exception occurred during PROPFIND request on '/<user>/calendar.ics/': Failed to load item 'KOrganizer-1994310660.776' in '<user>/calendar.ics': can't compare offset-naive and offset-aware datetimes
[pid: 1130|app: 0|req: 5778/41644] 192.168.200.20 (<user>) {74 vars in 1251 bytes} [Mon Apr  1 14:47:52 2019] PROPFIND /radicale/<user>/calendar.ics/ => generated 59 bytes in 449 msecs (HTTP/1.1 500) 2 headers in 84 bytes (2 switches on core 2)
[7fda9c71c700] ERROR: An exception occurred during PROPFIND request on '/<user>/calendar.ics/': Failed to load item 'KOrganizer-1994310660.776' in '<user>/calendar.ics': can't compare offset-naive and offset-aware datetimes
[pid: 1130|app: 0|req: 5779/41645] 192.168.200.20 (<user>) {74 vars in 1251 bytes} [Mon Apr  1 14:47:55 2019] PROPFIND /radicale/<user>/calendar.ics/ => generated 59 bytes in 436 msecs (HTTP/1.1 500) 2 headers in 84 bytes (2 switches on core 1)
[7fda9da86780] ERROR: An exception occurred during PROPFIND request on '/<user>/addressbook.vcf/': Failed to load item '1522939171.R947.vcf' in '<user>/addressbook.vcf': 'VCARD components must contain at least 1 FN'
[pid: 1129|app: 0|req: 32804/41646] 192.168.200.20 (<user>) {74 vars in 1260 bytes} [Mon Apr  1 14:47:58 2019] PROPFIND /radicale/<user>/addressbook.vcf/ => generated 59 bytes in 32 msecs (HTTP/1.1 500) 2 headers in 84 bytes (2 switches on core 0)

>From Korganizer, automatic connection, from the Debian stable machine.

[7fda9b71a700] ERROR: An exception occurred during REPORT request on '/<user>/calendar.ics/': Failed to load item 'KOrganizer-1994310660.776' in '<user>/calendar.ics': can't compare offset-naive and offset-aware datetimes
[pid: 1130|app: 0|req: 5780/41647] 192.168.200.12 (<user>) {82 vars in 1396 bytes} [Mon Apr  1 14:50:33 2019] REPORT /radicale/<user>/calendar.ics/ => generated 59 bytes in 445 msecs (HTTP/1.1 500) 2 headers in 84 bytes (2 switches on core 3)
[7fda9c71c700] ERROR: An exception occurred during REPORT request on '/<user>/calendar.ics/': Failed to load item 'KOrganizer-1994310660.776' in '<user>/calendar.ics': can't compare offset-naive and offset-aware datetimes
[pid: 1129|app: 0|req: 32806/41648] 192.168.200.12 (<user>) {82 vars in 1396 bytes} [Mon Apr  1 14:50:33 2019] REPORT /radicale/<user>/calendar.ics/ => generated 59 bytes in 754 msecs (HTTP/1.1 500) 2 headers in 84 bytes (1 switches on core 1)
[7fda93fff700] ERROR: An exception occurred during REPORT request on '/<user>/calendar.ics/': Failed to load item 'KOrganizer-1994310660.776' in '<user>/calendar.ics': can't compare offset-naive and offset-aware datetimes
[pid: 1129|app: 0|req: 32806/41649] 192.168.200.12 (<user>) {82 vars in 1396 bytes} [Mon Apr  1 14:50:33 2019] REPORT /radicale/<user>/calendar.ics/ => generated 59 bytes in 1088 msecs (HTTP/1.1 500) 2 headers in 84 bytes (1 switches on core 3)
[pid: 1129|app: 0|req: 32807/41650] 192.168.200.12 (<user>) {82 vars in 1398 bytes} [Mon Apr  1 14:50:34 2019] PROPFIND /radicale/<user>/calendar.ics/ => generated 260 bytes in 28 msecs (HTTP/1.1 207) 4 headers in 173 bytes (1 switches on core 2)
[pid: 1129|app: 0|req: 32808/41651] 192.168.200.12 (<user>) {82 vars in 1359 bytes} [Mon Apr  1 14:50:34 2019] PROPFIND /radicale/<user>/ => generated 208 bytes in 26 msecs (HTTP/1.1 207) 4 headers in 173 bytes (1 switches on core 0)
[7fda9da86780] ERROR: An exception occurred during PROPFIND request on '/<user>/': Failed to load item '1522939171.R947.vcf' in '<user>/addressbook.vcf': 'VCARD components must contain at least 1 FN'
[pid: 1130|app: 0|req: 5781/41652] 192.168.200.12 (<user>) {82 vars in 1359 bytes} [Mon Apr  1 14:50:34 2019] PROPFIND /radicale/<user>/ => generated 59 bytes in 49 msecs (HTTP/1.1 500) 2 headers in 84 bytes (2 switches on core 0)
[7fda9c71c700] ERROR: An exception occurred during PROPFIND request on '/<user>/calendar.ics/': Failed to load item 'KOrganizer-1994310660.776' in '<user>/calendar.ics': can't compare offset-naive and offset-aware datetimes
[pid: 1129|app: 0|req: 32809/41653] 192.168.200.12 (<user>) {82 vars in 1398 bytes} [Mon Apr  1 14:50:34 2019] PROPFIND /radicale/<user>/calendar.ics/ => generated 59 bytes in 533 msecs (HTTP/1.1 500) 2 headers in 84 bytes (2 switches on core 1)
[7fda93fff700] ERROR: An exception occurred during REPORT request on '/<user>/calendar.ics/': Failed to load item 'KOrganizer-1994310660.776' in '<user>/calendar.ics': can't compare offset-naive and offset-aware datetimes
[pid: 1129|app: 0|req: 32812/41654] 192.168.200.12 (<user>) {82 vars in 1396 bytes} [Mon Apr  1 14:55:33 2019] REPORT /radicale/<user>/calendar.ics/ => generated 59 bytes in 559 msecs (HTTP/1.1 500) 2 headers in 84 bytes (2 switches on core 3)
[7fda9bf1b700] ERROR: An exception occurred during REPORT request on '/<user>/calendar.ics/': Failed to load item 'KOrganizer-1994310660.776' in '<user>/calendar.ics': can't compare offset-naive and offset-aware datetimes
[pid: 1129|app: 0|req: 32812/41655] 192.168.200.12 (<user>) {82 vars in 1396 bytes} [Mon Apr  1 14:55:33 2019] REPORT /radicale/<user>/calendar.ics/ => generated 59 bytes in 945 msecs (HTTP/1.1 500) 2 headers in 84 bytes (2 switches on core 2)
[7fda9da86780] ERROR: An exception occurred during REPORT request on '/<user>/calendar.ics/': Failed to load item 'KOrganizer-1994310660.776' in '<user>/calendar.ics': can't compare offset-naive and offset-aware datetimes
[pid: 1129|app: 0|req: 32812/41656] 192.168.200.12 (<user>) {82 vars in 1396 bytes} [Mon Apr  1 14:55:33 2019] REPORT /radicale/<user>/calendar.ics/ => generated 59 bytes in 1340 msecs (HTTP/1.1 500) 2 headers in 84 bytes (2 switches on core 0)

apache2/access.log, from the android phone.

192.168.200.20 - <user> [01/Apr/2019:14:47:52 -0400] "PROPFIND /radicale/<user>/
calendar.ics/ HTTP/1.1" 500 1478 "-" "DAVdroid/1.9-ose (2017/10/19; dav4android;
 okhttp3) Android/4.2.2"
192.168.200.20 - <user> [01/Apr/2019:14:47:55 -0400] "PROPFIND /radicale/<user>/
calendar.ics/ HTTP/1.1" 500 1478 "-" "DAVdroid/1.9-ose (2017/10/19; dav4android;
 okhttp3) Android/4.2.2"
192.168.200.20 - <user> [01/Apr/2019:14:47:58 -0400] "PROPFIND /radicale/<user>/
addressbook.vcf/ HTTP/1.1" 500 1478 "-" "DAVdroid/1.9-ose (2017/10/19; dav4andro
id; okhttp3) Android/4.2.2"

apache2/access.log, from the Debian stable machine.

192.168.200.12 - - [01/Apr/2019:14:50:33 -0400] "REPORT /radicale/<user>/calenda
r.ics/ HTTP/1.1" 401 2209 "-" "Mozilla/5.0 (X11; Linux x86_64) KHTML/5.28.0 (lik
e Gecko) Konqueror/5.28"
192.168.200.12 - - [01/Apr/2019:14:50:33 -0400] "REPORT /radicale/<user>/calenda
r.ics/ HTTP/1.1" 401 2209 "-" "Mozilla/5.0 (X11; Linux x86_64) KHTML/5.28.0 (lik
e Gecko) Konqueror/5.28"
192.168.200.12 - - [01/Apr/2019:14:50:33 -0400] "REPORT /radicale/<user>/calenda
r.ics/ HTTP/1.1" 401 2209 "-" "Mozilla/5.0 (X11; Linux x86_64) KHTML/5.28.0 (like Gecko) Konqueror/5.28"
192.168.200.12 - <user> [01/Apr/2019:14:50:33 -0400] "REPORT /radicale/<user>/calendar.ics/ HTTP/1.1" 500 324 "-" "Mozilla/5.0 (X11; Linux x86_64) KHTML/5.28.0 (like Gecko) Konqueror/5.28"
192.168.200.12 - <user> [01/Apr/2019:14:50:33 -0400] "REPORT /radicale/<user>/calendar.ics/ HTTP/1.1" 500 324 "-" "Mozilla/5.0 (X11; Linux x86_64) KHTML/5.28.0 (like Gecko) Konqueror/5.28"
192.168.200.12 - <user> [01/Apr/2019:14:50:33 -0400] "REPORT /radicale/<user>/calendar.ics/ HTTP/1.1" 500 324 "-" "Mozilla/5.0 (X11; Linux x86_64) KHTML/5.28.0 (like Gecko) Konqueror/5.28"
192.168.200.12 - - [01/Apr/2019:14:50:34 -0400] "PROPFIND /radicale/<user>/calendar.ics/ HTTP/1.1" 401 2209 "-" "Mozilla/5.0 (X11; Linux x86_64) KHTML/5.28.0 (like Gecko) Konqueror/5.28"
192.168.200.12 - <user> [01/Apr/2019:14:50:34 -0400] "PROPFIND /radicale/<user>/calendar.ics/ HTTP/1.1" 207 650 "-" "Mozilla/5.0 (X11; Linux x86_64) KHTML/5.28.0 (like Gecko) Konqueror/5.28"
192.168.200.12 - - [01/Apr/2019:14:50:34 -0400] "PROPFIND /radicale/<user>/ HTTP/1.1" 401 749 "-" "Mozilla/5.0 (X11; Linux x86_64) KHTML/5.28.0 (like Gecko) Konqueror/5.28"
192.168.200.12 - <user> [01/Apr/2019:14:50:34 -0400] "PROPFIND /radicale/<user>/ HTTP/1.1" 207 598 "-" "Mozilla/5.0 (X11; Linux x86_64) KHTML/5.28.0 (like Gecko) Konqueror/5.28"

apache2/access.log, from the Debian testing machine.  This machine has no
events or addresses locally. Nothing shows up in Korgznizer or Kaddressbook.

[pid: 1129|app: 0|req: 32824/41668] 192.168.200.2 (<user>) {82 vars in 1447 bytes} [Mon Apr  1 15:10:37 2019] PROPFIND /radicale/<user>/calendar.vcs/ => generated 260 bytes in 27 msecs (HTTP/1.1 207) 4 headers in 173 bytes (1 switches on core 0)
[pid: 1129|app: 0|req: 32825/41669] 192.168.200.2 (<user>) {82 vars in 1408 bytes} [Mon Apr  1 15:10:37 2019] PROPFIND /radicale/<user>/ => generated 208 bytes in 26 msecs (HTTP/1.1 207) 4 headers in 173 bytes (2 switches on core 1)
[7fda9bf1b700] ERROR: An exception occurred during PROPFIND request on '/<user>/': Failed to load item '1522939171.R947.vcf' in '<user>/addressbook.vcf': 'VCARD components must contain at least 1 FN'
[pid: 1129|app: 0|req: 32826/41670] 192.168.200.2 (<user>) {82 vars in 1408 bytes} [Mon Apr  1 15:10:37 2019] PROPFIND /radicale/<user>/ => generated 59 bytes in 53 msecs (HTTP/1.1 500) 2 headers in 84 bytes (1 switches on core 2)
[7fda93fff700] ERROR: An exception occurred during PROPFIND request on '/<user>/calendar.vcs/': Failed to load item 'KOrganizer-417409544.764' in '<user>/calendar.vcs': At line 23: '20120226' is not a valid DATE-TIME
[pid: 1129|app: 0|req: 32827/41671] 192.168.200.2 (<user>) {82 vars in 1447 bytes} [Mon Apr  1 15:10:37 2019] PROPFIND /radicale/<user>/calendar.vcs/ => generated 59 bytes in 381 msecs (HTTP/1.1 500) 2 headers in 84 bytes (2 switches on core 3)
[pid: 1129|app: 0|req: 32828/41672] 192.168.200.2 (<user>) {82 vars in 1447 bytes} [Mon Apr  1 15:10:37 2019] PROPFIND /radicale/<user>/calendar.vcs/ => generated 260 bytes in 27 msecs (HTTP/1.1 207) 4 headers in 173 bytes (2 switches on core 0)
[pid: 1129|app: 0|req: 32829/41673] 192.168.200.2 (<user>) {82 vars in 1408 bytes} [Mon Apr  1 15:10:37 2019] PROPFIND /radicale/<user>/ => generated 208 bytes in 27 msecs (HTTP/1.1 207) 4 headers in 173 bytes (2 switches on core 1)
[7fda9bf1b700] ERROR: An exception occurred during PROPFIND request on '/<user>/': Failed to load item '1522939171.R947.vcf' in '<user>/addressbook.vcf': 'VCARD components must contain at least 1 FN'
[pid: 1129|app: 0|req: 32830/41674] 192.168.200.2 (<user>) {82 vars in 1408 bytes} [Mon Apr  1 15:10:37 2019] PROPFIND /radicale/<user>/ => generated 59 bytes in 48 msecs (HTTP/1.1 500) 2 headers in 84 bytes (1 switches on core 2)
[7fda9b71a700] ERROR: An exception occurred during PROPFIND request on '/<user>/calendar.vcs/': Failed to load item 'KOrganizer-417409544.764' in '<user>/calendar.vcs': At line 23: '20120226' is not a valid DATE-TIME

Thank you very much for the help so far!  Any further suggestions
greatly appreciated.

Augustine.