Re: [Dovecot] pop3 proxying error

Le 08/08/2012 15:41, Timo Sirainen a écrit :

On 8.8.2012, at 9.42, tonio@starbridge.org wrote:

...

I've just tried this patch, so far pop-login error doesnt shows up , but now I've got this one: (imap-login this time)

Aug 8 08:19:36 eol1 dovecot: imap-login: Fatal: master: service(imap-login): child 31887 killed with signal 6 (core dumped) .. #6 0xb779678d in hash_table_remove (table=0x83596b8, key=0x8833fe0) at hash.c:317 node = <optimized out> hash = 1839751767 #7 0xb778adda in setting_entry_detach (entry=0x8833fd0, cache=0x8057648) at master-service-settings-cache.c:167 I don't see how this could happen by looking at the code. I also can't reproduce this myself. Can you easily reproduce this? Could you run imap-login via valgrind (it slows things down):

service imap-login { executable = /usr/bin/valgrind -q --vgdb=no /usr/local/libexec/dovecot/imap-login }

(you may not have/need --vgdb=no, depends on your valgrind version)

Timo, I can'f find what trigger this error, and it seems only happenig under some load here the error log in mail.log: (by the way, this is not the same server than before, this one running a Debian Wheezy on a 2.6.32.2 linux kernel and 64 bits architecture.)

Aug 9 09:01:36 smtp dovecot: imap-login: Error: ==27313== Invalid read of size 4 Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== at 0x5069BA1: settings_parser_get_list (settings-parser.c:254) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x4E3EA7C: login_settings_read (login-settings.c:230) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x4E41347: ssl_servername_callback (ssl-proxy-openssl.c:1144) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x568F161: ??? (in /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x567B204: ??? (in /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x567F8C4: ??? (in /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x568C102: ??? (in /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x4E41AF0: ssl_step (ssl-proxy-openssl.c:465) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x4E3EE3D: client_connected_finish (main.c:139) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x508C3E4: master_service_listen (master-service.c:803) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x50A0275: io_loop_call_io (ioloop.c:379) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x50A0F06: io_loop_handler_run (ioloop-epoll.c:213) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== Address 0x65fc1e0 is 96 bytes inside a block of size 8,192 free'd Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== at 0x4C27D4E: free (vg_replace_malloc.c:427) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x508DC1E: master_service_settings_cache_read (master-service-settings-cache.c:168) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x4E3EA6A: login_settings_read (login-settings.c:226) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x4E41347: ssl_servername_callback (ssl-proxy-openssl.c:1144) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x568F161: ??? (in /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x567B204: ??? (in /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x567F8C4: ??? (in /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x568C102: ??? (in /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x4E41AF0: ssl_step (ssl-proxy-openssl.c:465) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x50A0275: io_loop_call_io (ioloop.c:379) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x50A0F06: io_loop_handler_run (ioloop-epoll.c:213) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x509FC87: io_loop_run (ioloop.c:398) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== Invalid read of size 4 Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== at 0x5069BB3: settings_parser_get_list (settings-parser.c:255) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x4E3EA7C: login_settings_read (login-settings.c:230) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x4E41347: ssl_servername_callback (ssl-proxy-openssl.c:1144) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x568F161: ??? (in /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x567B204: ??? (in /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x567F8C4: ??? (in /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x568C102: ??? (in /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x4E41AF0: ssl_step (ssl-proxy-openssl.c:465) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x4E3EE3D: client_connected_finish (main.c:139) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x508C3E4: master_service_listen (master-service.c:803) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x50A0275: io_loop_call_io (ioloop.c:379) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x50A0F06: io_loop_handler_run (ioloop-epoll.c:213) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== Address 0x65fc1e0 is 96 bytes inside a block of size 8,192 free'd Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== at 0x4C27D4E: free (vg_replace_malloc.c:427) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x508DC1E: master_service_settings_cache_read (master-service-settings-cache.c:168) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x4E3EA6A: login_settings_read (login-settings.c:226) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x4E41347: ssl_servername_callback (ssl-proxy-openssl.c:1144) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x568F161: ??? (in /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x567B204: ??? (in /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x567F8C4: ??? (in /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x568C102: ??? (in /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x4E41AF0: ssl_step (ssl-proxy-openssl.c:465) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x50A0275: io_loop_call_io (ioloop.c:379) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x50A0F06: io_loop_handler_run (ioloop-epoll.c:213) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== by 0x509FC87: io_loop_run (ioloop.c:398) Aug 9 09:01:37 smtp dovecot: imap-login: Error: ==27313== Aug 9 09:01:37 smtp dovecot: imap-login: Panic: file login-settings.c: line 232 (login_settings_read): assertion failed: (cache_sets[count] == NULL)

backtrace on vgcore:

gdb /usr/lib/dovecot/imap-login /root/vgcore.27313 GNU gdb (GDB) 7.4.1-debian Copyright (C) 2012 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later http://gnu.org/licenses/gpl.html This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "x86_64-linux-gnu". For bug reporting instructions, please see: http://www.gnu.org/software/gdb/bugs/... Reading symbols from /usr/lib/dovecot/imap-login...done.

warning: core file may not match specified executable file. [New LWP 27313] [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1". Core was generated by '. Program terminated with signal 6, Aborted. #0 0x0000000005311475 in *__GI_raise (sig=<optimized out>) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64 64 ../nptl/sysdeps/unix/sysv/linux/raise.c: Aucun fichier ou dossier de ce type. (gdb) bt full #0 0x0000000005311475 in *__GI_raise (sig=<optimized out>) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64 pid = <optimized out> selftid = <optimized out> #1 0x00000000053146f0 in *__GI_abort () at abort.c:92 act = {__sigaction_handler = {sa_handler = 0x4e45130, sa_sigaction = 0x4e45130}, sa_mask = {__val = {34342962424, 84234600, 67249360, 84246240, 4294967295, 86924192, 67250608, 2684328, 4294967295, 34342962672, 1, 2679208, 0, 34342962672, 113514016, 84197376}}, sa_flags = 67164658, sa_restorer = 0x1} sigs = {__val = {32, 0 <repeats 15 times>}} #2 0x0000000005093538 in default_fatal_finish (type=<optimized out>, status=status@entry=0) at failures.c:191 backtrace = 0x76d2364 "\003\003P#P1" #3 0x000000000509356e in i_internal_fatal_handler (ctx=0x7ff0004e0, format=<optimized out>, args=<optimized out>) at failures.c:649 status = 0 #4 0x0000000005067efa in i_panic (format=format@entry=0x4e45130 "file %s: line %d (%s): assertion failed: (%s)") at failures.c:263 ctx = {type = LOG_TYPE_PANIC, exit_status = 0, timestamp = 0x0} args = {{gp_offset = 40, fp_offset = 48, overflow_arg_area = 0x7ff0005d0, reg_save_area = 0x7ff000510}} #5 0x0000000004e3ecd4 in login_settings_read (pool=0x8783670, local_ip=local_ip@entry=0xafce3e4, remote_ip=remote_ip@entry=0xafce3f8, local_name=<optimized out>, other_settings_r=other_settings_r@entry=0x7ff000698) at login-settings.c:232 input = {roots = 0x6056c0, config_path = 0x0, preserve_environment = false, preserve_user = false, preserve_home = false, never_exec = false, use_sysexits = false, parse_full_config = false, module = 0x4043b4 "imap-login", service = 0x4043af "imap", username = 0x0, local_ip = {family = 2, u = {ip6 = { __in6_u = {__u6_addr8 = "Wb§e", '\000' , __u6_addr16 = {25175, 26023, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {1705468503, 0, 0, 0}}}, ip4 = {s_addr = 1705468503}}}, remote_ip = {family = 2, u = { ip6 = {__in6_u = {__u6_addr8 = ".ilÒ", '\000' , __u6_addr16 = {26926, 53868, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {3530320174, 0, 0, 0}}}, ip4 = {s_addr = 3530320174}}}, local_name = 0x75f1b00 "imap.spamguard.fr"} error = <optimized out> parser = 0x65fc1c0 cache_sets = 0x6c41628 sets = <optimized out> i = <optimized out> count = <optimized out> ---Type <return> to continue, or q <return> to quit--- __FUNCTION__ = "login_settings_read" #6 0x0000000004e41348 in ssl_servername_callback (ssl=0x6cf8c70, al=<optimized out>, context=<optimized out>) at ssl-proxy-openssl.c:1144 ctx = <optimized out> proxy = <optimized out> client = 0xafce360 host = <optimized out> other_sets = 0x1 #7 0x000000000568f162 in ?? () from /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0 No symbol table info available. #8 0x000000000567b205 in ?? () from /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0 No symbol table info available. #9 0x000000000567f8c5 in ?? () from /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0 No symbol table info available. #10 0x000000000568c103 in ?? () from /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0 No symbol table info available. #11 0x0000000004e41af1 in ssl_handshake (proxy=0x7010e10) at ssl-proxy-openssl.c:465 ret = <optimized out> #12 ssl_step (proxy=0x7010e10) at ssl-proxy-openssl.c:528 No locals. #13 0x0000000004e420c5 in ssl_proxy_start (proxy=<optimized out>) at ssl-proxy-openssl.c:658 No locals. #14 0x0000000004e3ee3e in client_connected_finish (conn=0x7ff000880) at main.c:139 client = 0xafce360 proxy = 0x7010e10 local_ip = {family = 2, u = {ip6 = {__in6_u = {__u6_addr8 = "Wb§e", '\000' , __u6_addr16 = { 25175, 26023, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {1705468503, 0, 0, 0}}}, ip4 = {s_addr = 1705468503}}} set = 0x87836a8 local_port = 993 pool = 0x8783670 fd_ssl = <optimized out> other_sets = 0x8783698 #15 0x000000000508c3e5 in master_service_listen (l=0x7187990) at master-service.c:803 service = 0x64ef820 ---Type <return> to continue, or q <return> to quit--- conn = {fd = 141, listen_fd = 9, name = 0x64efd3a "imaps", remote_ip = {family = 2, u = {ip6 = {__in6_u = { __u6_addr8 = ".ilÒ", '\000' , __u6_addr16 = {26926, 53868, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {3530320174, 0, 0, 0}}}, ip4 = {s_addr = 3530320174}}}, remote_port = 34589, fifo = 0, ssl = 1, accepted = 1} #16 0x00000000050a0276 in io_loop_call_io (io=0x7187bd0) at ioloop.c:379 ioloop = 0x64efa10 t_id = 2 #17 0x00000000050a0f07 in io_loop_handler_run (ioloop=ioloop@entry=0x64efa10) at ioloop-epoll.c:213 ctx = 0x7185c80 events = 0x0 event = 0xae5d410 list = 0x7187c50 io = <optimized out> tv = {tv_sec = 54, tv_usec = 854242} events_count = <optimized out> msecs = <optimized out> ret = 1 i = <optimized out> call = <optimized out> #18 0x000000000509fc88 in io_loop_run (ioloop=0x64efa10) at ioloop.c:398 No locals. #19 0x000000000508bd23 in master_service_run (service=0x64ef820, callback=callback@entry=0x4e3f060 ) at master-service.c:543 No locals. #20 0x0000000004e3f6fe in login_binary_run (binary=<optimized out>, argc=2, argv=0x64ef450) at main.c:406 set_pool = 0x64eff90 allow_core_dumps = <optimized out> login_socket = <optimized out> c = <optimized out> #21 0x00000000052fdead in __libc_start_main (main=<optimized out>, argc=<optimized out>, ubp_av=<optimized out>, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7ff000b38) at libc-start.c:228 result = <optimized out> unwind_buf = {cancel_jmp_buf = {{jmp_buf = {0, 4734455784457788985, 4203696, 34342964032, 0, 0, 4736613026474909241, 4734444482055265849}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x4041a0, ---Type <return> to continue, or q <return> to quit--- 0x7ff000b48}, data = {prev = 0x0, cleanup = 0x0, canceltype = 4211104}}} not_first_call = <optimized out> #22 0x00000000004024d9 in _start () No symbol table info available.