search

etesync / etesync-dav

This is a CalDAV and CardDAV adapter for EteSync
https://www.etesync.com
GNU General Public License v3.0
290 stars 47 forks source link

etesync-dav uses 1½ hours of CPU time in 43 hours #206

Open stuart12 opened 3 years ago

stuart12 commented 3 years ago

Etesync-dav uses too much CPU time and network bandwidth. It would use even more CPU time if I didn't limit it with CPUQuota=25% and CPUSchedulingPolicy=batch. At the moment, I am using Thunderbird 78.8.0 without any active plugins so I am just synchronising my calendar. Whenever I restart etesync-dav it downloads and uses the latest version without discarding the cache. I synchronise to my own etesync server at etesync.pook.it (I presume that you can probe it to see what version it is running). I have 2 Android devices also synchronising to my server. How can I stop etesync-dav using so much CPU and network bandwidth?

I have just stopped Thunderbird and etesync-dav is still using 25% of a CPU (which is its limit).

:; systemctl status etesync-dav@stuart.service 
● etesync-dav@stuart.service - EteSync CalDAV and CardDAV front-end/proxy for stuart
     Loaded: loaded (/etc/systemd/system/etesync-dav@.service; enabled; vendor preset: enabled)
    Drop-In: /etc/systemd/system/etesync-dav@.service.d
             └─override.conf
     Active: active (running) since Mon 2021-03-15 20:32:31 -03; 1 day 19h ago
       Docs: https://github.com/etesync/etesync-dav
    Process: 1692 ExecStartPre=mkdir -p -m 0700 $HOME $ETESYNC_DATA_DIR (code=exited, status=0/SUCCESS)
    Process: 1946 ExecStartPre=sh -c runuser -u stuart -- sh -c "tar -C \$HOME/.local/share/etesync-dav -hc $CONFFILES || tar -c --files-from /dev/null" > /run/etesync-dav@stuart/creds.tar (code=exited, status=0/SUCCESS)
    Process: 1950 ExecStartPre=tar -C ${ETESYNC_DATA_DIR} --unlink-first -f /run/etesync-dav@stuart/creds.tar -x (code=exited, status=0/SUCCESS)
    Process: 1952 ExecStartPre=pip3 --cache-dir /var/cache/etesync-dav@stuart/pip3-cache $PIP_ARGS install --no-warn-script-location $PIP_MODULES (code=exited, status=0/SUCCESS)
   Main PID: 1970 (etesync-dav)
         IP: 557.0K in, 10.8M out
      Tasks: 3 (limit: 50)
     Memory: 421.9M (high: 512.0M)
        CPU: 1h 32min 36.137s
     CGroup: /system.slice/system-etesync\x2ddav.slice/etesync-dav@stuart.service
             └─1970 /usr/bin/python3 /tmp/etesync-dav@stuart/.local/bin/etesync-dav

My etesync server prints messages such as:

2021-03-17T18:41:32.192471842Z INFO:     192.168.42.2:55026 - "GET /console/ HTTP/1.0" 400 Bad Request
2021-03-17T18:41:32.522418456Z INFO:     192.168.42.2:55030 - "POST /Autodiscover/Autodiscover.xml HTTP/1.0" 400 Bad Request
2021-03-17T18:41:34.249626258Z INFO:     192.168.42.2:55032 - "GET /_ignition/execute-solution HTTP/1.0" 400 Bad Request
2021-03-17T18:41:34.299202906Z INFO:     192.168.42.2:55034 - "POST /api/jsonws/invoke HTTP/1.0" 400 Bad Request
2021-03-17T18:41:36.619093762Z INFO:     192.168.42.2:55036 - "GET /?XDEBUG_SESSION_START=phpstorm HTTP/1.0" 400 Bad Request
2021-03-17T18:41:45.040204297Z INFO:     192.168.42.2:55044 - "POST /api/v1/collection/list_multi/?stoken=pc1AlpWckxHuSZtJTLfOYDilYcuChCcP HTTP/1.0" 200 OK
2021-03-17T18:50:29.101211188Z INFO:     192.168.42.2:58584 - "POST /api/v1/collection/list_multi/?stoken=pc1AlpWckxHuSZtJTLfOYDilYcuChCcP HTTP/1.0" 200 OK
2021-03-17T18:53:36.543757861Z INFO:     192.168.42.2:59186 - "GET /api/v1/user/stuart/ HTTP/1.0" 404 Not Found
2021-03-17T18:53:37.931884646Z INFO:     192.168.42.2:59188 - "POST /api/v1/user/ HTTP/1.0" 404 Not Found
2021-03-17T18:56:46.388071984Z INFO:     192.168.42.2:59868 - "POST /api/v1/collection/list_multi/?stoken=pc1AlpWckxHuSZtJTLfOYDilYcuChCcP HTTP/1.0" 200 OK
2021-03-17T18:58:05.220708580Z INFO:     192.168.42.2:60112 - "POST /api/v1/collection/list_multi/?stoken=g5ymeRuqr1rXoTWQlVCv-etd5I-93fxL HTTP/1.0" 200 OK
2021-03-17T18:58:06.239277405Z INFO:     192.168.42.2:60118 - "GET /api/v1/collection/J_NqYOvKup7OiE7Dn4Fn7t31rog8u323/item/?stoken=qR94vly7_HVfX4LLQbF0KVZ15xd15eJB HTTP/1.0" 200 OK
2021-03-17T18:58:12.630768069Z INFO:     192.168.42.2:60170 - "POST /api/v1/collection/list_multi/?stoken=pc1AlpWckxHuSZtJTLfOYDilYcuChCcP HTTP/1.0" 200 OK
2021-03-17T19:01:50.097499109Z INFO:     192.168.42.2:60898 - "POST /api/v1/collection/list_multi/?stoken=pc1AlpWckxHuSZtJTLfOYDilYcuChCcP HTTP/1.0" 200 OK

A strace, sudo strace -t -s4 -fp 1970, on the etesync process shows:

[pid 735918] 16:15:55 getrandom("\x95\x06\xc8\x3a"..., 16, 0) = 16
[pid 735918] 16:15:56 pread64(13, "\r\0\0\0"..., 4096, 16891904) = 4096
[pid 735918] 16:15:56 pread64(13, "\n\0\0\0"..., 4096, 30322688) = 4096
[pid 735918] 16:15:56 getrandom("\xdb\x4c\xca\xf2"..., 16, 0) = 16
[pid 735918] 16:15:56 mmap(NULL, 262144, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7efc054c0000
[pid 735918] 16:15:56 pread64(13, "\r\0\0\0"..., 4096, 16896000) = 4096
[pid 735918] 16:15:56 getrandom("\x07\x3a\x70\xa5"..., 16, 0) = 16
[pid 735918] 16:15:56 pread64(13, "\r\0\0\0"..., 4096, 16900096) = 4096
[pid 735918] 16:15:56 pread64(13, "\n\0\0\0"..., 4096, 30691328) = 4096
[pid 735918] 16:15:56 getrandom("\x18\x38\xdf\x4b"..., 16, 0) = 16
[pid 735918] 16:15:56 pread64(13, "\r\0\0\0"..., 4096, 16904192) = 4096
[pid 735918] 16:15:56 getrandom("\x63\x85\xc4\xed"..., 16, 0) = 16
[pid 735918] 16:15:56 pread64(13, "\r\0\0\0"..., 4096, 16908288) = 4096
[pid 735918] 16:15:56 getrandom("\xf9\x77\xea\xfb"..., 16, 0) = 16
[pid 735918] 16:15:56 pread64(13, "\r\0\0\0"..., 4096, 16912384) = 4096
[pid 735918] 16:15:56 getrandom("\xfc\x1a\x64\x4c"..., 16, 0) = 16
[pid 735918] 16:15:56 pread64(13, "\r\0\0\0"..., 4096, 16916480) = 4096
[pid 735918] 16:15:56 getrandom("\xa4\xa6\x72\x15"..., 16, 0) = 16
[pid 735918] 16:15:56 pread64(13, "\r\0\0\0"..., 4096, 16920576) = 4096
[pid 735918] 16:15:56 getrandom("\xae\x71\x59\x8c"..., 16, 0) = 16
[pid 735918] 16:15:56 pread64(13, "\r\0\0\0"..., 4096, 16928768) = 4096
[pid 735918] 16:15:56 getrandom("\xf9\x91\x51\x89"..., 16, 0) = 16
[pid 735918] 16:15:56 mmap(NULL, 262144, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7efc05480000
[pid 735918] 16:15:56 pread64(13, "\r\0\0\0"..., 4096, 16932864) = 4096
[pid 735918] 16:15:56 getrandom("\x26\xc4\x80\x7d"..., 16, 0) = 16
[pid 735918] 16:15:57 pread64(13, "\r\0\0\0"..., 4096, 16936960) = 4096

PS. How can I tell what version my server is running?

And many thanks for giving us etesync.

tasn commented 3 years ago

Server is running: there's no easy way. It looks like it's stuck in a loop for whatever reason. It will be hard to debug... :| You can also try the nuclear option of stopping etesync-dav, moving over the data dir, and starting with etesync-dav from scratch (it'll sync once and then it'll be the same). I really have no idea what's up. :(

stuart12 commented 3 years ago

hi, we discussed this problem a few months ago on Matrix. What do I need to copy over? I presume that I can just delete the cache and it will be rebuilt. I have removed all plugins from Thunderbird (78.8.0) and am just syncing the calendar using the built-in connector. (TbSync refused to even contact my etesync-dav server on localhost.)

It appears that I'm running whatever code I got when I cloned https://github.com/etesync/server.git. I should put the SHA1 in a file.

I also download my contacts using a python script every day or so.

I don't see what I could be doing to make etesync-dav loop. it doesn't immediately start looping. At the moment it isn't but it has exchanged a lot of data for 29 hours.

● etesync-dav@stuart.service - EteSync CalDAV and CardDAV front-end/proxy for stuart
     Loaded: loaded (/etc/systemd/system/etesync-dav@.service; enabled; vendor preset: enabled)
    Drop-In: /etc/systemd/system/etesync-dav@.service.d
             └─override.conf
     Active: active (running) since Wed 2021-03-17 16:27:05 -03; 1 day 5h ago
       Docs: https://github.com/etesync/etesync-dav
    Process: 736582 ExecStartPre=mkdir -p -m 0700 $HOME $ETESYNC_DATA_DIR (code=exited, status=0/SUCCESS)
    Process: 736586 ExecStartPre=sh -c runuser -u stuart -- sh -c "tar -C \$HOME/.local/share/etesync-dav -hc $CONFFILES || tar -c --files-from /dev/null" > /run/etesync-dav@stuart/creds.tar (code=exited, status=0/SUCCESS)
    Process: 736590 ExecStartPre=tar -C ${ETESYNC_DATA_DIR} --unlink-first -f /run/etesync-dav@stuart/creds.tar -x (code=exited, status=0/SUCCESS)
    Process: 736593 ExecStartPre=pip3 --cache-dir /var/cache/etesync-dav@stuart/pip3-cache $PIP_ARGS install --no-warn-script-location $PIP_MODULES (code=exited, status=0/SUCCESS)
   Main PID: 736606 (etesync-dav)
         IP: 1.1M in, 2.4M out
      Tasks: 4 (limit: 50)
     Memory: 379.1M (high: 512.0M)
        CPU: 12min 45.505s
     CGroup: /system.slice/system-etesync\x2ddav.slice/etesync-dav@stuart.service
             └─736606 /usr/bin/python3 /tmp/etesync-dav@stuart/.local/bin/etesync-dav
stuart12 commented 2 years ago

hello, I have deleted the cache many times. I see this problem on two different machines (both running Debian/unstable). It does not start immediately but modifying a calendar entry with thunderbird is enough to make it start burning CPU. On this machine thunderbird is not using tbsync, the other machine it is. Etesync-dav is using all the CPU it can get and is doing (sudo strace -fp55622):

[pid 60946] 15:37:53 mmap(NULL, 262144, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fadf7340000
[pid 60946] 15:37:53 pread64(13, "\r\0\0\0\1\10\211\0\10\211\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096, 23527424) = 4096
[pid 60946] 15:37:53 getrandom("\xa0\xe7\x44\x6f\x06\x7f\xb6\x36\x0b\x5a\xcd\x3d\x7c\x08\x70\x18", 16, 0) = 16
[pid 60946] 15:37:53 pread64(13, "\r\0\0\0\1\6\200\0\6\200\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096, 23535616) = 4096
[pid 60946] 15:37:53 pread64(13, "\0\0\0\0\314\225-\314\305\314\204\314\350\314\216v\22\314\356\314\216\314\360!64{\314\224\314\346B"..., 4096, 23531520) = 4096
[pid 60946] 15:37:53 getrandom("\xd6\x35\x93\x56\x6f\x60\x92\x54\x8c\x30\x4d\x50\x77\x1f\xcc\x29", 16, 0) = 16
[pid 60946] 15:37:53 pread64(13, "\r\0\0\0\1\6\235\0\6\235\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096, 23543808) = 4096
[pid 60946] 15:37:53 pread64(13, "\0\0\0\0006\314\364\314\212\314\2312\314\311/\314\244\36F(q\314\363\314\337)\314\252\314\365\314\314"..., 4096, 23539712) = 4096
[pid 60946] 15:37:53 getrandom("\x95\x47\xa6\x1a\x47\xfa\x76\x15\x2e\x17\x4d\xcc\xb9\x42\xc1\x29", 16, 0) = 16
[pid 60946] 15:37:53 pread64(13, "\r\0\0\0\1\6\330\0\6\330\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096, 23552000) = 4096
[pid 60946] 15:37:53 pread64(13, "\0\0\0\0\314\305\314\327\314\221c\314\274\314\212\314\271f\21D\314\365\314\336\314\227\314\326\314\334\314\240"..., 4096, 23547904) = 4096
[pid 60946] 15:37:53 getrandom("\x9d\xaa\x33\x2a\x68\xa9\x2c\x59\x5a\x81\x31\xbf\xef\xab\x06\x8d", 16, 0) = 16
[pid 60946] 15:37:54 pread64(13, "\r\0\0\0\1\10d\0\10d\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096, 23556096) = 4096
[pid 60946] 15:37:54 pread64(13, "\r\0\0\0\1\6_\0\6_\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096, 23564288) = 4096
[pid 60946] 15:37:54 pread64(13, "\0\0\0\0\314\310w\314\371~=\314\263\314\207\314\200\314\333\314\217\37|4\314\300\r\314\315\314\251\34"..., 4096, 23560192) = 4096
[pid 60946] 15:37:54 getrandom("\x0d\xff\x66\x5c\xa4\x37\x93\x83\x62\xaf\x96\xbd\x49\x0c\xe2\x5d", 16, 0) = 16
[pid 60946] 15:37:54 mmap(NULL, 262144, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fadf7300000
[pid 60946] 15:37:54 pread64(13, "\r\0\0\0\1\10t\0\10t\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096, 23568384) = 4096
[pid 60946] 15:37:54 getrandom("\x0a\x5f\xe1\x72\xa0\xf2\x69\x25\x64\xa1\x25\xe3\x2e\x06\x2d\xa3", 16, 0) = 16
[pid 60946] 15:37:54 pread64(13, "\r\0\0\0\1\6\210\0\6\210\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096, 23576576) = 4096
[pid 60946] 15:37:54 pread64(13, "\0\0\0\0\2360\314\337\314\342SY\314\210\314\351h\314\372O\314\310\0371\2k\314\326Z\314\333y"..., 4096, 23572480) = 4096
[pid 60946] 15:37:54 getrandom("\xbf\x12\xf2\x65\x1e\x2a\x19\xff\x45\x86\x7f\xb2\x16\x65\xb1\x7d", 16, 0) = 16
[pid 60946] 15:37:54 pread64(13, "\r\0\0\0\1\2{\0\2{\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096, 23580672) = 4096
[pid 60946] 15:37:54 getrandom("\xac\xf8\x64\xe5\x12\x16\xea\x41\xfd\x3b\xbb\xf9\xc3\x9b\x9f\x6c", 16, 0) = 16
[pid 60946] 15:37:55 pread64(13, "\r\0\0\0\2\0\332\0\10R\0\332\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096, 23584768) = 4096
[pid 60946] 15:37:55 pread64(13, "\n\0\0\0Q\2\266\0\10J\17\326\17\254\17\202\17X\17.\17\4\16\332\16\260\16\206\16\\\0162"..., 4096, 31379456) = 4096
[pid 60946] 15:37:55 getrandom("\x76\xf2\x38\xe4\x5b\x9b\x48\xbe\x5e\x4d\x86\xb5\x14\x16\xe4\x1d", 16, 0) = 16
[pid 60946] 15:37:55 pread64(13, "\r\0\0\0\1\2\34\0\2\34\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096, 23588864) = 4096
[pid 60946] 15:37:55 getrandom("\x45\xb5\x6d\xc0\x3d\xf9\x1f\x57\x1e\x57\xa4\xe7\xa2\x96\x26\x77", 16, 0) = 16
[pid 60946] 15:37:55 mmap(NULL, 262144, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fadf72c0000

What is file descriptor 13?

:; sudo ls -l /proc/60946/fd
total 0
lr-x------ 1 etesync-dav etesync-dav 64 Oct 15 15:28 0 -> /dev/null
lrwx------ 1 etesync-dav etesync-dav 64 Oct 15 15:28 1 -> 'socket:[726708]'
lrwx------ 1 etesync-dav etesync-dav 64 Oct 15 15:28 10 -> 'anon_inode:[eventpoll]'
lr-x------ 1 etesync-dav etesync-dav 64 Oct 15 15:28 11 -> 'pipe:[757524]'
l-wx------ 1 etesync-dav etesync-dav 64 Oct 15 15:28 12 -> 'pipe:[757524]'
lrwx------ 1 etesync-dav etesync-dav 64 Oct 15 15:28 13 -> /var/cache/private/etesync-dav@stuart/data/etebase_data.db
lrwx------ 1 etesync-dav etesync-dav 64 Oct 15 15:28 14 -> /var/cache/private/etesync-dav@stuart/data/etebase_data.db-wal
lrwx------ 1 etesync-dav etesync-dav 64 Oct 15 15:28 15 -> /var/cache/private/etesync-dav@stuart/data/etebase_data.db-shm
lrwx------ 1 etesync-dav etesync-dav 64 Oct 15 15:28 2 -> 'socket:[726708]'
lrwx------ 1 etesync-dav etesync-dav 64 Oct 15 15:28 3 -> 'socket:[728123]'
lrwx------ 1 etesync-dav etesync-dav 64 Oct 15 15:28 4 -> 'socket:[728124]'
lrwx------ 1 etesync-dav etesync-dav 64 Oct 15 15:28 5 -> 'socket:[726721]'
lrwx------ 1 etesync-dav etesync-dav 64 Oct 15 15:28 6 -> 'socket:[726726]'
lrwx------ 1 etesync-dav etesync-dav 64 Oct 15 15:28 7 -> 'socket:[763712]'
lrwx------ 1 etesync-dav etesync-dav 64 Oct 15 15:28 8 -> 'socket:[763713]'
lrwx------ 1 etesync-dav etesync-dav 64 Oct 15 15:28 9 -> 'socket:[763714]'
:; sudo ls -Ll /proc/60946/fd
total 31228
crw-rw-rw- 1 root        root            1, 3 Oct 14 11:25 0
srwxrwxrwx 1 root        root               0 Jan  1  1970 1
?rw------- 1 root        root               0 Oct 14 11:25 10
prw------- 1 etesync-dav etesync-dav        0 Oct 15 15:27 11
prw------- 1 etesync-dav etesync-dav        0 Oct 15 15:27 12
-rw-r--r-- 1 etesync-dav etesync-dav 31944704 Oct 15 15:27 13
-rw-r--r-- 1 etesync-dav etesync-dav        0 Oct 15 15:27 14
-rw-r--r-- 1 etesync-dav etesync-dav    32768 Oct 15 15:27 15
srwxrwxrwx 1 root        root               0 Jan  1  1970 2
srwxrwxrwx 1 etesync-dav etesync-dav        0 Jan  1  1970 3
srwxrwxrwx 1 etesync-dav etesync-dav        0 Jan  1  1970 4
srwxrwxrwx 1 etesync-dav etesync-dav        0 Jan  1  1970 5
srwxrwxrwx 1 etesync-dav etesync-dav        0 Jan  1  1970 6
srwxrwxrwx 1 etesync-dav etesync-dav        0 Jan  1  1970 7
srwxrwxrwx 1 etesync-dav etesync-dav        0 Jan  1  1970 8
srwxrwxrwx 1 etesync-dav etesync-dav        0 Jan  1  1970 9

The process 60946 is not doing anything except pread64, getrandom and mmap.

stuart12 commented 2 years ago

When I start etesync using systemd, the journal gives a list of all the packages etesync-dav is using. Is there anything unexpected? My etesync-dav is using lots of system packages. I presume that this is OK:

Oct 15 15:46:43 spook-7480latitude systemd[1]: Starting EteSync CalDAV and CardDAV front-end/proxy for stuart...
Oct 15 15:47:15 spook-7480latitude pip3[61716]: Collecting etesync-dav
Oct 15 15:47:15 spook-7480latitude pip3[61716]:   Using cached etesync_dav-0.30.8-py3-none-any.whl
Oct 15 15:47:17 spook-7480latitude pip3[61716]: Collecting etebase>=0.30.0
Oct 15 15:47:17 spook-7480latitude pip3[61716]:   Using cached etebase-0.31.2-cp39-cp39-manylinux2010_x86_64.whl (4.3 MB)
Oct 15 15:47:17 spook-7480latitude pip3[61716]: Requirement already satisfied: appdirs>=1.4.3 in /usr/lib/python3/dist-packages (from etesync-dav) (1.4.4)
Oct 15 15:47:17 spook-7480latitude pip3[61716]: Requirement already satisfied: msgpack>=1.0.0 in /usr/lib/python3/dist-packages (from etesync-dav) (1.0.2)
Oct 15 15:47:18 spook-7480latitude pip3[61716]: Collecting Radicale<=3.1.0,>=3.0.3
Oct 15 15:47:18 spook-7480latitude pip3[61716]:   Using cached Radicale-3.0.6-py3-none-any.whl (122 kB)
Oct 15 15:47:18 spook-7480latitude pip3[61716]: Requirement already satisfied: Flask-WTF>=0.14.2 in /usr/lib/python3/dist-packages (from etesync-dav) (0.14.3)
Oct 15 15:47:18 spook-7480latitude pip3[61716]: Collecting etesync>=0.12.1
Oct 15 15:47:18 spook-7480latitude pip3[61716]:   Using cached etesync-0.12.1-py3-none-any.whl
Oct 15 15:47:18 spook-7480latitude pip3[61716]: Requirement already satisfied: Flask>=1.1.1 in /usr/lib/python3/dist-packages (from etesync-dav) (2.0.1)
Oct 15 15:47:18 spook-7480latitude pip3[61716]: Requirement already satisfied: requests[socks]>=2.21 in /usr/lib/python3/dist-packages (from etesync-dav) (2.25.1)
Oct 15 15:47:18 spook-7480latitude pip3[61716]: Requirement already satisfied: python-dateutil>=2.6 in /usr/lib/python3/dist-packages (from etesync>=0.12.1->etesync-dav) (2.8.1)
Oct 15 15:47:18 spook-7480latitude pip3[61716]: Requirement already satisfied: pytz>=2019.1 in /usr/lib/python3/dist-packages (from etesync>=0.12.1->etesync-dav) (2021.3)
Oct 15 15:47:18 spook-7480latitude pip3[61716]: Requirement already satisfied: vobject>=0.9 in /usr/lib/python3/dist-packages (from etesync>=0.12.1->etesync-dav) (0.9.6.1)
Oct 15 15:47:18 spook-7480latitude pip3[61716]: Requirement already satisfied: asn1crypto>=0.22 in /usr/lib/python3/dist-packages (from etesync>=0.12.1->etesync-dav) (1.4.0)
Oct 15 15:47:18 spook-7480latitude pip3[61716]: Requirement already satisfied: furl>=0.5 in /usr/lib/python3/dist-packages (from etesync>=0.12.1->etesync-dav) (2.1.0)
Oct 15 15:47:18 spook-7480latitude pip3[61716]: Requirement already satisfied: idna>=2.5 in /usr/lib/python3/dist-packages (from etesync>=0.12.1->etesync-dav) (2.10)
Oct 15 15:47:18 spook-7480latitude pip3[61716]: Requirement already satisfied: pycparser>=2.17 in /usr/lib/python3/dist-packages (from etesync>=0.12.1->etesync-dav) (2.20)
Oct 15 15:47:18 spook-7480latitude pip3[61716]: Requirement already satisfied: peewee>=3.7.0 in /usr/lib/python3/dist-packages (from etesync>=0.12.1->etesync-dav) (3.14.4)
Oct 15 15:47:18 spook-7480latitude pip3[61716]: Requirement already satisfied: py>=1.4 in /usr/lib/python3/dist-packages (from etesync>=0.12.1->etesync-dav) (1.10.0)
Oct 15 15:47:18 spook-7480latitude pip3[61716]: Requirement already satisfied: cryptography>=3.0 in /usr/lib/python3/dist-packages (from etesync>=0.12.1->etesync-dav) (3.3.2)
Oct 15 15:47:18 spook-7480latitude pip3[61716]: Requirement already satisfied: orderedmultidict>=0.7 in /usr/lib/python3/dist-packages (from etesync>=0.12.1->etesync-dav) (1.0)
Oct 15 15:47:18 spook-7480latitude pip3[61716]: Requirement already satisfied: pyasn1>=0.2 in /usr/lib/python3/dist-packages (from etesync>=0.12.1->etesync-dav) (0.4.8)
Oct 15 15:47:18 spook-7480latitude pip3[61716]: Requirement already satisfied: pyparsing>=2.2 in /usr/lib/python3/dist-packages (from etesync>=0.12.1->etesync-dav) (2.4.7)
Oct 15 15:47:18 spook-7480latitude pip3[61716]: Requirement already satisfied: packaging>=16.8 in /usr/lib/python3/dist-packages (from etesync>=0.12.1->etesync-dav) (21.0)
Oct 15 15:47:18 spook-7480latitude pip3[61716]: Requirement already satisfied: six>=1.10 in /usr/lib/python3/dist-packages (from etesync>=0.12.1->etesync-dav) (1.16.0)
Oct 15 15:47:18 spook-7480latitude pip3[61716]: Requirement already satisfied: cffi>=1.10 in /usr/lib/python3/dist-packages (from etesync>=0.12.1->etesync-dav) (1.14.6)
Oct 15 15:47:19 spook-7480latitude pip3[61716]: Requirement already satisfied: passlib in /usr/lib/python3/dist-packages (from Radicale<=3.1.0,>=3.0.3->etesync-dav) (1.7.4)
Oct 15 15:47:19 spook-7480latitude pip3[61716]: Requirement already satisfied: defusedxml in /usr/lib/python3/dist-packages (from Radicale<=3.1.0,>=3.0.3->etesync-dav) (0.7.1)
Oct 15 15:47:19 spook-7480latitude pip3[61716]: Requirement already satisfied: PySocks!=1.5.7,>=1.5.6 in /usr/lib/python3/dist-packages (from requests[socks]>=2.21->etesync-dav) (1.7.1)
Oct 15 15:47:21 spook-7480latitude pip3[61716]: Installing collected packages: Radicale, etesync, etebase, etesync-dav
Oct 15 15:47:23 spook-7480latitude pip3[61716]: Successfully installed Radicale-3.0.6 etebase-0.31.2 etesync-0.12.1 etesync-dav-0.30.8
Oct 15 15:47:24 spook-7480latitude systemd[1]: Started EteSync CalDAV and CardDAV front-end/proxy for stuart.
stuart12 commented 2 years ago

My etesync server is at 453869d71d04b2bc454126e60515aa09a7bcb8b9. Is there any more debug information that I can give you?

tasn commented 2 years ago

I don't know where to even start. :( I think the best way is to run it with some sort of a python profiler so we know where it's stuck.

stuart12 commented 2 years ago

Are versions of the different pip packages shown above known good versions? Perhaps I should force pip to use exactly the versions that you do.

tasn commented 2 years ago

The ones we use are probably better tested, though it really shouldn't matter (or so I hope).

stuart12 commented 2 years ago

hi, I think that I need to fix this problem or stop using etesync. Can you suggest a python profiler or give any more advice on how to debug this problem? Not only does etesync-dav use all the cpu time that it can get but thunderbird also losses updates to calendar entries and says 

An error occurred when writing to the calendar etesync! Please see below for more information.
Error code: MODIFICATION_FAILED
Description:

Etesync-dav says:

Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]: [2021-11-11 11:26:59 +0100] [1862/Thread-3] [ERROR] database is locked
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]: Traceback (most recent call last):
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:   File "/usr/lib/python3/dist-packages/peewee.py", line 3144, in execute_sql
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:     cursor.execute(sql, params or ())
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]: sqlite3.OperationalError: database is locked
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]: During handling of the above exception, another exception occurred:
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]: Traceback (most recent call last):
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:   File "/tmp/etesync-dav@stuart/.local/lib/python3.9/site-packages/etesync_dav/radicale/storage.py", line 84, in run
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:     etesync.sync()
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:   File "/tmp/etesync-dav@stuart/.local/lib/python3.9/site-packages/etesync_dav/local_cache/__init__.py", line 92, in sync
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:     self.sync_collection(collection.uid)
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:   File "/tmp/etesync-dav@stuart/.local/lib/python3.9/site-packages/etesync_dav/local_cache/__init__.py", line 157, in sync_collection
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:     self.push_collection(uid)
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:   File "/tmp/etesync-dav@stuart/.local/lib/python3.9/site-packages/etesync_dav/local_cache/__init__.py", line 225, in push_collection
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:     cache_item.save()
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:   File "/usr/lib/python3/dist-packages/peewee.py", line 6554, in save
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:     rows = self.update(**field_dict).where(self._pk_expr()).execute()
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:   File "/usr/lib/python3/dist-packages/peewee.py", line 1907, in inner
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:     return method(self, database, *args, **kwargs)
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:   File "/usr/lib/python3/dist-packages/peewee.py", line 1978, in execute
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:     return self._execute(database)
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:   File "/usr/lib/python3/dist-packages/peewee.py", line 2474, in _execute
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:     cursor = database.execute(self)
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:   File "/usr/lib/python3/dist-packages/peewee.py", line 3157, in execute
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:     return self.execute_sql(sql, params, commit=commit)
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:   File "/usr/lib/python3/dist-packages/peewee.py", line 3151, in execute_sql
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:     self.commit()
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:   File "/usr/lib/python3/dist-packages/peewee.py", line 2917, in __exit__
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:     reraise(new_type, new_type(exc_value, *exc_args), traceback)
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:   File "/usr/lib/python3/dist-packages/peewee.py", line 190, in reraise
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:     raise value.with_traceback(tb)
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:   File "/usr/lib/python3/dist-packages/peewee.py", line 3144, in execute_sql
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]:     cursor.execute(sql, params or ())
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]: peewee.OperationalError: database is locked
Nov 11 11:26:59 spook-7480latitude etesync-dav[1862]: [2021-11-11 11:26:59 +0100] [1862/Thread-31] [ERROR] An exception occurred during PUT request on '/stuart/J_NqYOvKup7OiE7Dn4Fn7t31XXXXXXXXXXXX08-44e6-b2a4-3bbddd3c7171.ics': database is locked

Should I restart etesync when I see database is locked?

This thunderbird is not using any add-ons. My other machine had the tbsync add-on and saw the same errors (until its CPU fried).

tasn commented 2 years ago

Interesting that you are still getting the database is locked error, I wonder why it happens. :| Either way, this error should be recoverable I believe.

Anyhow, for a profile, I've previously used: https://github.com/benfred/py-spy

Sorry for the trouble. :|

stuart12 commented 2 years ago

My etebase_data.db is 31 MB (32342016 bytes). Is this unusually big? Do I have more calendar entries than normal?