Solved Problems with Thunderbird

Barzakhi · Jun 20, 2021

A few days ago I installed FreeBSD 13.0-RELEASE-p1 on a new laptop.
I would like to use the current version of Thunderbird 78.11.0 as my email client.
After going through the initial setup of email accounts I restarted
the Thunderbird. It came up but after a few seconds it was hanging.

The same version of Thunderbird on my old laptop running also FreeBSD 13.0-RELEASE-p1 works without any problems.

Using truss(1) I checked the syscalls. The syscalls of working Thuderbird has the following pattern:

Code:

...
poll({ 4/POLLIN 5/POLLIN 18/POLLIN },3,0)        = 0 (0x0)
write(19,"\M-z",1)                               = 1 (0x1)
recvmsg(4,0x7fffffffdbf0,0)                      ERR#35 'Resource temporarily unavailable'
recvmsg(4,0x7fffffffdc20,0)                      ERR#35 'Resource temporarily unavailable'
poll({ 4/POLLIN 5/POLLIN 18/POLLIN },3,-1)       = 1 (0x1)
read(18,"\M-z",1)                                = 1 (0x1)
recvmsg(4,0x7fffffffdbf0,0)                      ERR#35 'Resource temporarily unavailable'
recvmsg(4,0x7fffffffdc20,0)                      ERR#35 'Resource temporarily unavailable'
poll({ 4/POLLIN 5/POLLIN 18/POLLIN },3,0)        = 0 (0x0)
recvmsg(4,0x7fffffffdbf0,0)                      ERR#35 'Resource temporarily unavailable'
recvmsg(4,0x7fffffffdc20,0)                      ERR#35 'Resource temporarily unavailable'
poll({ 4/POLLIN 5/POLLIN 18/POLLIN },3,0)        = 0 (0x0)
recvmsg(4,0x7fffffffdbf0,0)                      ERR#35 'Resource temporarily unavailable'
recvmsg(4,0x7fffffffdc20,0)                      ERR#35 'Resource temporarily unavailable'
poll({ 4/POLLIN 5/POLLIN 18/POLLIN },3,0)        = 0 (0x0)
recvmsg(4,0x7fffffffdbf0,0)                      ERR#35 'Resource temporarily unavailable'
recvmsg(4,0x7fffffffdc20,0)                      ERR#35 'Resource temporarily unavailable'
poll({ 4/POLLIN 5/POLLIN 18/POLLIN },3,0)        = 0 (0x0)
recvmsg(4,0x7fffffffdbf0,0)                      ERR#35 'Resource temporarily unavailable'
recvmsg(4,0x7fffffffdc20,0)                      ERR#35 'Resource temporarily unavailable'
_umtx_op(0x803af81d0,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x18,0x7fffded8abe8) ERR#60 'Operation timed out'
write(19,"\M-z",1)                               = 1 (0x1)
poll({ 4/POLLIN 5/POLLIN 18/POLLIN },3,-1)       = 1 (0x1)
read(18,"\M-z",1)                                = 1 (0x1)
recvmsg(4,0x7fffffffdbf0,0)                      ERR#35 'Resource temporarily unavailable'
recvmsg(4,0x7fffffffdc20,0)                      ERR#35 'Resource temporarily unavailable'
poll({ 4/POLLIN 5/POLLIN 18/POLLIN },3,0)        = 0 (0x0)
recvmsg(4,0x7fffffffdbf0,0)                      ERR#35 'Resource temporarily unavailable'
recvmsg(4,0x7fffffffdc20,0)                      ERR#35 'Resource temporarily unavailable'
poll({ 4/POLLIN 5/POLLIN 18/POLLIN },3,0)        = 0 (0x0)
recvmsg(4,0x7fffffffdbf0,0)                      ERR#35 'Resource temporarily unavailable'
recvmsg(4,0x7fffffffdc20,0)                      ERR#35 'Resource temporarily unavailable'
poll({ 4/POLLIN 5/POLLIN 18/POLLIN },3,0)        = 0 (0x0)
recvmsg(4,0x7fffffffdbf0,0)                      ERR#35 'Resource temporarily unavailable'
recvmsg(4,0x7fffffffdc20,0)                      ERR#35 'Resource temporarily unavailable'
poll({ 4/POLLIN 5/POLLIN 18/POLLIN },3,0)        = 0 (0x0)
recvmsg(4,0x7fffffffdbf0,0)                      ERR#35 'Resource temporarily unavailable'
recvmsg(4,0x7fffffffdc20,0)                      ERR#35 'Resource temporarily unavailable'
_umtx_op(0x803af81d0,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x18,0x7fffded8abe8) ERR#60 'Operation timed out'
...

For the hanging Thunderbird I got

Code:

...
_umtx_op(0x80110e548,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x18,0x7fffdd973ad8) ERR#60 'Operation timed out'
_umtx_op(0x80110e4d0,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x18,0x7fffddab8ad8) ERR#60 'Operation timed out'
_umtx_op(0x80110e578,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x18,0x7fffdd8f1ad8) ERR#60 'Operation timed out'
poll({ 15/POLLIN|POLLPRI 110/POLLIN|POLLPRI 95/POLLIN|POLLPRI 94/POLLIN|POLLPRI 92/POLLIN|POLLPRI 91/POLLIN|POLLPRI 93/POLLIN|POLLPRI },7,288183) = 0 (0x0)
setsockopt(110,IPPROTO_TCP,TCP_NODELAY,0x7fffdffbc830,4) = 0 (0x0)
sendto(110,"\^W\^C\^C\0\^S\M-&\^E\M-x\M-Y"...,24,0,NULL,0) = 24 (0x18)
close(110)                                       = 0 (0x0)
poll({ 15/POLLIN|POLLPRI 93/POLLIN|POLLPRI 95/POLLIN|POLLPRI 94/POLLIN|POLLPRI 92/POLLIN|POLLPRI 91/POLLIN|POLLPRI },6,0) = 0 (0x0)
_umtx_op(0x80110e530,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x18,0x7fffdd9b4ad8) ERR#60 'Operation timed out'
_umtx_op(0x80110e518,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x18,0x7fffdd9f5ad8) ERR#60 'Operation timed out'
_umtx_op(0x80110e548,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x18,0x7fffdd973ad8) ERR#60 'Operation timed out'
_umtx_op(0x80110e4d0,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x18,0x7fffddab8ad8) ERR#60 'Operation timed out'
_umtx_op(0x80110e578,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x18,0x7fffdd8f1ad8) ERR#60 'Operation timed out'
_umtx_op(0x80110e530,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x18,0x7fffdd9b4ad8) ERR#60 'Operation timed out'
_umtx_op(0x80110e518,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x18,0x7fffdd9f5ad8) ERR#60 'Operation timed out'
_umtx_op(0x80110e548,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x18,0x7fffdd973ad8) ERR#60 'Operation timed out'
_umtx_op(0x80110e4d0,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x18,0x7fffddab8ad8) ERR#60 'Operation timed out'
_umtx_op(0x80110e578,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x18,0x7fffdd8f1ad8) ERR#60 'Operation timed out'
...

After a while one sees only the syscall _umtx_op().
Here are some syscall statistics generated by truss -c -D -H -s 256 -p pid during a run of hanging Thunderbird :

Code:

syscall                     seconds   calls  errors
write                   0.000365902       2       0
setsockopt              0.000063767       1       0
sendto                  0.000254046       2       0
recvfrom                0.000128818       2       2
read                    0.000265710       2       0
poll                    1.500617733       5       0
close                   0.000082416       1       0
_umtx_op               95.721207180    1302    1298
                      ------------- ------- -------
                       97.222985572    1317    1300

syscall                     seconds   calls  errors
_umtx_op               24.912572144    1514    1514
                      ------------- ------- -------
                       24.912572144    1514    1514

syscall                     seconds   calls  errors
_umtx_op              104.401716108    2013    2013
                      ------------- ------- -------
                      104.401716108    2013    2013

syscall                     seconds   calls  errors
_umtx_op              148.017649304    1863    1863
                      ------------- ------- -------
                      148.017649304    1863    1863

ktrace() shows the following messages in the hanging state:

Code:

....
61336 IMAP     RET   _umtx_op -1 errno 60 Operation timed out
61336 IMAP     CALL  _umtx_op(0x80110e548,0xf<UMTX_OP_WAIT_UINT_PRIVATE>,0,0x18,0x7fffdd973ad8)
61336 IMAP     RET   _umtx_op -1 errno 60 Operation timed out
61336 IMAP     CALL  _umtx_op(0x80110e4d0,0xf<UMTX_OP_WAIT_UINT_PRIVATE>,0,0x18,0x7fffddab8ad8)
61336 IMAP     RET   _umtx_op -1 errno 60 Operation timed out
61336 IMAP     CALL  _umtx_op(0x80110e578,0xf<UMTX_OP_WAIT_UINT_PRIVATE>,0,0x18,0x7fffdd8f1ad8)
61336 IMAP     RET   _umtx_op -1 errno 60 Operation timed out
61336 IMAP     CALL  _umtx_op(0x80110e530,0xf<UMTX_OP_WAIT_UINT_PRIVATE>,0,0x18,0x7fffdd9b4ad8)
61336 IMAP     RET   _umtx_op -1 errno 60 Operation timed out
61336 IMAP     CALL  _umtx_op(0x80110e518,0xf<UMTX_OP_WAIT_UINT_PRIVATE>,0,0x18,0x7fffdd9f5ad8)
61336 IMAP     RET   _umtx_op -1 errno 60 Operation timed out
61336 IMAP     CALL  _umtx_op(0x80110e548,0xf<UMTX_OP_WAIT_UINT_PRIVATE>,0,0x18,0x7fffdd973ad8)
61336 IMAP     RET   _umtx_op -1 errno 60 Operation timed out
61336 IMAP     CALL  _umtx_op(0x80110e4d0,0xf<UMTX_OP_WAIT_UINT_PRIVATE>,0,0x18,0x7fffddab8ad8)
61336 IMAP     RET   _umtx_op -1 errno 60 Operation timed out
61336 IMAP     CALL  _umtx_op(0x80110e578,0xf<UMTX_OP_WAIT_UINT_PRIVATE>,0,0x18,0x7fffdd8f1ad8)

Any idea how to get around this problem?

grahamperrin · Jun 26, 2021

I can't interpret the debug information (sorry), but you could try safe mode:

Barzakhi · Jun 29, 2021

I have also tried the safe mode thunderbird -safe-mode.
But It didn't lead to any new findings!

Because I couldn't narrow down the problem using the output of
truss(1) and ktrace(1) I have tried to get some insights by switching on the Thunderbird's logging:

Code:

$ export NSPR_LOG_MODULES=IMAP:5
$ export NSPR_LOG_FILE=/tmp/thunderbird_`date "+%Y%m%d_%H%M%S"`.log
$ thunderbird &

Strangely the Thunderbird was now responsive and it worked flawlessly.
After that I stopped the Thunderbird and left the logging session and
started it again as usual. From now on it worked without any problems.

Switching on the Thunderbird's logging produced a huge amount of entries
recording the Thunderbird's activities in great detail.

I don't have any idea what was the impact of switching on the Thunderbird's logging
on this problem and why the Thunderbird works properly now.

Here is a sample of syscall statistics for a working Thunderbird:

Code:

$ truss -c -D -H -s 256 -p 15033
syscall                     seconds   calls  errors
sigfastblock            0.000100011       1       0
thr_new                 0.000120604       1       0
getegid                 0.000354852       6       0
getgid                  0.000358174       6       0
geteuid                 0.000607577       9       0
getuid                  0.001087353      18       0
cpuset_getaffinity      0.005601750      35       0
getpid                  0.003897005      46       0
writev                  0.010009252      55       0
write                   0.177351833    1809       0
unlink                  0.002478200      10       3
thr_set_name            0.000150669       2       0
thr_self                0.021155612     246       0
__sysctl                0.050155869      21       0
statfs                  0.000181039       1       0
socket                  0.000427500       3       0
sigprocmask             0.000602132      10       0
setsockopt              0.001710901      16       0
sendto                  0.002074326      12       0
rename                  0.001469733       7       0
recvmsg                 0.542253283    6471    6416
recvfrom                0.007190797      77      23
read                    0.194893253    2085       0
poll                   26.362584276    4393       0
pathconf                0.000078442       1       0
openat                  0.014070311      83      21
open                    0.002664736      22       5
mprotect                0.141029927    1944       0
mmap                    0.001475822      19       0
mkdir                   0.000752317      11      11
madvise                 0.010310649     130       0
lseek                   0.104136138    1521       0
getsockopt              0.000157208       2       0
getsockname             0.000159232       2       0
getrusage               0.019500525     260       0
getpeername             0.000998128       8       4
getdirentries           0.002842155      13       0
fsync                   0.045848038       9       0
fstatat                 0.059354979     387      54
fstat                   0.005032637      65       0
fcntl                   0.006673562      95       0
connect                 0.000475200       3       2
close                   0.006312176      69       0
access                  0.007735972      91       8
_umtx_op              139.022064185    3805     293
__realpathat            0.010038249      75       0
                      ------------- ------- -------
                      166.848526589   23955    6840

I mark this thread as solved without knowing what caused the problem and how it has been resolved.

grahamperrin · Jun 29, 2021

Thanks.

I might have expected improvement from a single start in ~~safe~~ troubleshooting mode (possible non-documented features of this mode) followed by a start in normal mode …

… if the subsequent logging somehow did the trick, that's neat.

PS <https://hg.mozilla.org/comm-central/file/tip/mail/base/content/troubleshootMode.js> // Delete the xulstore file.

Solved Problems with Thunderbird

Barzakhi

grahamperrin

Barzakhi

grahamperrin