Bug 730788 – [IMAPx] Deadlock during IDLE start

After an evaluation, GNOME has moved from Bugzilla to GitLab. Learn more about GitLab.
No new issues can be reported in GNOME Bugzilla anymore.
To report an issue in a GNOME project, go to GNOME GitLab.
Do not go to GNOME Gitlab for: Bluefish, Doxygen, GnuCash, GStreamer, java-gnome, LDTP, NetworkManager, Tomboy.

Bug 730788 - [IMAPx] Deadlock during IDLE start


Summary:	[IMAPx] Deadlock during IDLE start


Status:	RESOLVED FIXED

Product:	evolution-data-server
Classification:	Platform
Component:	Mailer
Version:	3.13.x (obsolete)
Hardware:	Other Linux

Importance:	Normal normal
Target Milestone:	---
Assigned To:	evolution-mail-maintainers
QA Contact:	Evolution QA team

URL:
Whiteboard:

Depends on:
Blocks:

Reported:	2014-05-27 07:12 UTC by Yanko Kaneti
Modified:	2014-07-08 14:32 UTC

See Also:
GNOME target:	---
GNOME version:	---

Attachments
process pstack (22.32 KB, text/plain) 2014-05-27 07:31 UTC, Yanko Kaneti		Details
proposed eds patch (716 bytes, patch) 2014-05-27 07:46 UTC, Milan Crha	none	Details \| Review
proposed eds patch ][ (905 bytes, patch) 2014-05-27 07:49 UTC, Milan Crha	committed	Details \| Review

Description Yanko Kaneti 2014-05-27 07:12:21 UTC

Here is a CAMEL_DEBUG=all log of imapx:A getting stuck  with evolution/eds 3.13.2. The UI is responsive, there are two spinners in the status bar a "Refreshing folder INBOX" and "Expunging folder 'INBOX'" 
.......
[imapx:A] ** Starting next command
[imapx:A] adding command, format = 'EXPUNGE'
[imapx:A] completing command buffer is [7] 'EXPUNGE'
[imapx:A] enqueue job 'EXPUNGE'
[imapx:A] * no, no jobs
[imapx:A] adding command, format = 'IDLE'
[imapx:A] completing command buffer is [4] 'IDLE'
[imapx:A] ** Starting next command
[imapx:A] - we're selected on 'INBOX', current jobs?
[imapx:A] -- Checking job queue
[imapx:A] -- 150 'EXPUNGE'?
[imapx:A] --> starting 'EXPUNGE'
[imapx:A] completing command buffer is [0] ''
[imapx:A] Starting command (active=1,) A00126 EXPUNGE
[imapx:A] I/O: 'A00126 EXPUNGE'
[imapx:A] ** Starting next command
[imapx:A] I/O: '* 36971 EXPUNGE
* 36970 EXPUNGE
A00126 OK Expunge completed.'
[imapx:A] got untagged response
[imapx:A] Have token 'EXPUNGE' id 36971
Thread 0x7f8f8c007680 >
Get folder info(0xc782f0:0, '<null>') =
  full_name: INBOX
  flags: 00000454
    full_name: INBOX/Archive
    flags: 00000008
.............................
imapx_find_connection_unlocked: for-expensive:0 will return:(nil) cmd-count:-2 has-expensive:-2 found:0; connections opened:1 max:2
   cmds:1 has-expensive:0 avail:0 cinfo:0x7f8f8c0038f0 server:0x7f8f8c0021b0
.............................
  full_name: .#evolution/Trash
  flags: 00000cf2
  full_name: .#evolution/Junk
  flags: 000010f2
< 0x7f8f8c007680 >
[imapx:B] I/O: '* PREAUTH [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS SPECIAL-USE BINARY MOVE] Logged in as yaneti'
.....

Comment 1 Yanko Kaneti 2014-05-27 07:31:08 UTC

Created attachment 277260 [details]
process pstack

Comment 2 Milan Crha 2014-05-27 07:45:11 UTC

Pasting backtrace inline:

+ Trace 233635

Thread 16 (Thread 0x7f8f7bfff700 (LWP 2355))

#0 __lll_lock_wait
at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S line 135
#1 __GI___pthread_mutex_lock
at ../nptl/pthread_mutex_lock.c line 114
#2 imapx_match_active_job
at camel-imapx-server.c line 1736
#3 imapx_untagged_expunge
at camel-imapx-server.c line 1884
#4 imapx_untagged
at camel-imapx-server.c line 2974
#5 imapx_step
at camel-imapx-server.c line 3350
#6 imapx_ready_to_read
at camel-imapx-server.c line 7504
#7 g_main_dispatch
at gmain.c line 3064
#8 g_main_context_dispatch
at gmain.c line 3663
#9 g_main_context_iterate
at gmain.c line 3734
#10 g_main_loop_run
at gmain.c line 3928
#11 imapx_parser_thread
at camel-imapx-server.c line 7610
#12 g_thread_proxy
at gthread.c line 764
#13 start_thread
at pthread_create.c line 310
#14 clone
at ../sysdeps/unix/sysv/linux/x86_64/clone.S line 109

Thread 6 (Thread 0x7f8f98df3700 (LWP 2396))

#0 __lll_lock_wait
at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S line 135
#1 __GI___pthread_mutex_lock
at ../nptl/pthread_mutex_lock.c line 134
#2 g_mutex_lock
at gthread-posix.c line 209
#3 imapx_in_idle
at camel-imapx-server.c line 3833
#4 imapx_command_start_next
at camel-imapx-server.c line 1454
#5 imapx_unregister_job
at camel-imapx-server.c line 1037
#6 imapx_job_idle_start
at camel-imapx-server.c line 3565
#7 camel_imapx_job_run
at camel-imapx-job.c line 255
#8 imapx_submit_job
at camel-imapx-server.c line 1050
#9 camel_imapx_server_idle
at camel-imapx-server.c line 3592
#10 imapx_call_idle
at camel-imapx-server.c line 3672
#11 g_main_dispatch
at gmain.c line 3064
#12 g_main_context_dispatch
at gmain.c line 3663
#13 g_main_context_iterate
at gmain.c line 3734
#14 g_main_loop_run
at gmain.c line 3928
#15 imapx_idle_thread
at camel-imapx-server.c line 3744
#16 g_thread_proxy
at gthread.c line 764
#17 start_thread
at pthread_create.c line 310
#18 clone
at ../sysdeps/unix/sysv/linux/x86_64/clone.S line 109

Thread 4 (Thread 0x7f8f99df5700 (LWP 2595))

#0 __lll_lock_wait
at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S line 135
#1 __GI___pthread_mutex_lock
at ../nptl/pthread_mutex_lock.c line 114
#2 camel_imapx_server_ref_job
at camel-imapx-server.c line 9333
#3 camel_imapx_store_ref_job
at camel-imapx-store.c line 3297
#4 imapx_server_ref_job
at camel-imapx-server.c line 1792
#5 camel_imapx_server_refresh_info
at camel-imapx-server.c line 8518
#6 imapx_refresh_info_sync
at camel-imapx-folder.c line 842
#7 camel_folder_refresh_info_sync
at camel-folder.c line 3489
#8 refresh_folders_exec
at mail-send-recv.c line 1032
#9 mail_msg_proxy
at mail-mt.c line 373
#10 g_thread_pool_thread_proxy
at gthreadpool.c line 307
#11 g_thread_proxy
at gthread.c line 764
#12 start_thread
at pthread_create.c line 310
#13 clone
at ../sysdeps/unix/sysv/linux/x86_64/clone.S line 109

Comment 3 Milan Crha 2014-05-27 07:46:51 UTC

Created attachment 277262 [details] [review]
proposed eds patch

for evolution-data-server;

There seem to happen a deadlock in IDLE processing, a race between the idle_lock and the queue lock. Please test this patch.

Comment 4 Milan Crha 2014-05-27 07:49:42 UTC

Created attachment 277263 [details] [review]
proposed eds patch ][

for evolution-data-server;

Oops, no, this one will be better. It makes sure that he queue lock and the idle_lock are not held at once.

Comment 5 Yanko Kaneti 2014-05-27 08:44:07 UTC

Running with attachment 277263 [details] [review] for a while now and it seems to work where before it got stuck in the first few minutes of use.

Thanks

Comment 6 Milan Crha 2014-05-27 09:14:25 UTC

Thanks for the testing.

Created commit 14f4897 in eds master (3.13.3+) [1]
Created commit 920750e in eds evolution-data-server-3-12 (3.12.3+)

[1] https://git.gnome.org/browse/evolution-data-server/commit/?id=14f4897

Comment 7 Milan Crha 2014-07-08 14:25:00 UTC

It seems I caused a regression with this patch, reported as bug #732366.

Comment 8 Yanko Kaneti 2014-07-08 14:32:41 UTC

I've seen the behavior described in 732366 before the patch here.
My attempt to describe it was bug 725720