[Dovecot] pop3 proxying error

tonio at starbridge.org tonio at starbridge.org
Thu Aug 9 10:15:12 EEST 2012


Le 08/08/2012 15:41, Timo Sirainen a écrit :
> On 8.8.2012, at 9.42, tonio at 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 at 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 at 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 at entry=0xafce3e4,
     remote_ip=remote_ip at entry=0xafce3f8, local_name=<optimized out>, 
other_settings_r=other_settings_r at 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' <repeats 11 
times>, __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' <repeats 11 
times>, __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' <repeats 11 times>, __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' <repeats 11 times>, 
__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 at 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 at entry=0x4e3f060 <client_connected>)
     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.





More information about the dovecot mailing list