[Dovecot] pop3 proxying error

tonio＠starbridge.org

7 Aug 2012 7 Aug '12

2:47 p.m.

Hi Timo, I've got some errors with pop3 proxying and dovecot 2.1.9

I's occured on the proxy side:

Aug 7 13:16:47 dev1 dovecot: pop3-login: Fatal: master: service(pop3-login): child 23046 killed with signal 11 (core dumped)

Server side shows no error, and runs the same dovecot version.

Thanks for your help. Best regards Tonio Buonaguidi

Core dump:

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 "i486-linux-gnu". For bug reporting instructions, please see: http://www.gnu.org/software/gdb/bugs/... Reading symbols from /usr/lib/dovecot/pop3-login...done. [New LWP 23046]

warning: Can't read pathname for load map: Erreur d'entrée/sortie. [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib/i386-linux-gnu/i686/cmov/libthread_db.so.1". Core was generated by `dovecot/pop3-login -D'. Program terminated with signal 11, Segmentation fault. #0 settings_parser_dup (old_ctx=0x8783480, new_pool=0x632e6465) at settings-parser.c:1742 1742 pool_ref(new_pool);

doveconf -n # 2.1.9: /etc/dovecot/dovecot.conf # OS: Linux 2.6.32.2-xxxx-std-ipv6-32 i686 Debian wheezy/sid auth_cache_size = 4 k auth_mechanisms = plain login director_mail_servers = bb.bb.bb.bb cc.cc.cc.cc director_servers = dd.dd.dd.dd aa.aa.aa.aa log_timestamp = %Y-%m-%d %H:%M:%S mail_debug = yes managesieve_notify_capability = mailto managesieve_sieve_capability = comparator-i;octet comparator-i;ascii-casemap fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date spamtest spamtestplus virustest passdb { args = /etc/dovecot/dovecot-sql.conf driver = sql } protocols = imap pop3 sieve service auth { unix_listener /var/spool/postfix/private/auth { group = mail mode = 0660 user = postfix } unix_listener auth-master { mode = 0660 user = vmail } unix_listener auth-userdb { mode = 0660 user = vmail } } service director { fifo_listener login/proxy-notify { mode = 0666 } inet_listener { address = aa.aa.aa.aa port = 9090 } unix_listener director-userdb { mode = 0600 } unix_listener login/director { mode = 0666 } } service imap-login { executable = imap-login director inet_listener imap { address = aa.aa.aa.aa yy.yyy.yy.yy xx.xx.xx.xx port = 143 } inet_listener imaps { address = aa.aa.aa.aa yy.yyy.yy.yy xx.xx.xx.xx port = 993 } process_limit = 256 process_min_avail = 2 service_count = 0 vsz_limit = 256 M } service managesieve-login { inet_listener sieve { address = aa.aa.aa.aa yy.yyy.yy.yy xx.xx.xx.xx port = 4190 } vsz_limit = 64 M } service pop3-login { executable = pop3-login -D inet_listener pop3 { address = aa.aa.aa.aa yy.yyy.yy.yy xx.xx.xx.xx port = 110 } inet_listener pop3s { address = aa.aa.aa.aa yy.yyy.yy.yy xx.xx.xx.xx port = 995 } service_count = 0 } ssl_ca =

Show replies by date

tonio＠starbridge.org

7 Aug 7 Aug

3:54 p.m.

Le 07/08/2012 13:47, tonio@starbridge.org a écrit :

...

Hi Timo, I've got some errors with pop3 proxying and dovecot 2.1.9

I's occured on the proxy side:

Aug 7 13:16:47 dev1 dovecot: pop3-login: Fatal: master: service(pop3-login): child 23046 killed with signal 11 (core dumped)

Server side shows no error, and runs the same dovecot version.

Thanks for your help. Best regards Tonio Buonaguidi

Core dump:

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 "i486-linux-gnu". For bug reporting instructions, please see: http://www.gnu.org/software/gdb/bugs/... Reading symbols from /usr/lib/dovecot/pop3-login...done. [New LWP 23046]

warning: Can't read pathname for load map: Erreur d'entrée/sortie. [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib/i386-linux-gnu/i686/cmov/libthread_db.so.1". Core was generated by `dovecot/pop3-login -D'. Program terminated with signal 11, Segmentation fault. #0 settings_parser_dup (old_ctx=0x8783480, new_pool=0x632e6465) at settings-parser.c:1742 1742 pool_ref(new_pool);

sorry I've forgot bt full !

(gdb) bt full #0 settings_parser_dup (old_ctx=0xa26920, new_pool=0x6d6f632e32) at settings-parser.c:1742 new_ctx = <optimized out> iter = <optimized out> new_link = <optimized out> links = <optimized out> key = <optimized out> value = <optimized out> i = <optimized out> parser_pool = <optimized out> __FUNCTION__ = "settings_parser_dup" #1 0x00007fc7a77c3ecc in cache_add (parser=0xa26920, output=0x7ffffe4557f0, input=0x7ffffe455790, cache=0x60ea50) at master-service-settings-cache.c:221 entry = 0xe98b90 pool = 0xe98b70 pool_size = <optimized out> entry_local_name = 0xe98b90 "pop.te.com" #2 master_service_settings_cache_read (cache=0x60ea50, input=<optimized out>, dyn_parsers=<optimized out>, parser_r=0x7ffffe4558b8, error_r=<optimized out>) at master-service-settings-cache.c:297 output = {specific_services = 0x0, service_uses_local = 1, service_uses_remote = 0, used_local = 1, used_remote = 0} new_input = {roots = 0x604500, config_path = 0x0, preserve_environment = false, preserve_user = false, preserve_home = false, never_exec = false, use_sysexits = false, parse_full_config = false, module = 0x403640 "pop3-login", service = 0x40363b "pop3", username = 0x0, local_ip = {family = 2, u = {ip6 = { __in6_u = {__u6_addr8 = ".iHb", '\000' , __u6_addr16 = {26926, 25160, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {1648912686, 0, 0, 0}}}, ip4 = {s_addr = 1648912686}}}, remote_ip = {family = 2, u = { ip6 = {__in6_u = {__u6_addr8 = "ZT\220]", '\000' , __u6_addr16 = {21594, 23952, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {1569739866, 0, 0, 0}}}, ip4 = {s_addr = 1569739866}}}, local_name = 0x9fa1d0 "pop.te.com"} set = <optimized out> __FUNCTION__ = "master_service_settings_cache_read" #3 0x00007fc7a7a25a1b in login_settings_read (pool=0xbc54e0, local_ip=<optimized out>, remote_ip=<optimized out>, local_name=<optimized out>, other_settings_r=0x7ffffe455908) at login-settings.c:226 input = {roots = 0x604500, config_path = 0x0, preserve_environment = false, preserve_user = false, preserve_home = false, never_exec = false, use_sysexits = false, parse_full_config = false, module = 0x403640 "pop3-login", service = 0x40363b "pop3", username = 0x0, local_ip = {family = 2, u = {ip6 = { ---Type <return> to continue, or q <return> to quit--- __in6_u = {__u6_addr8 = ".iHb", '\000' , __u6_addr16 = {26926, 25160, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {1648912686, 0, 0, 0}}}, ip4 = {s_addr = 1648912686}}}, remote_ip = {family = 2, u = { ip6 = {__in6_u = {__u6_addr8 = "ZT\220]", '\000' , __u6_addr16 = {21594, 23952, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {1569739866, 0, 0, 0}}}, ip4 = {s_addr = 1569739866}}}, local_name = 0x9fa1d0 "pop.te.com"} error = <optimized out> parser = <optimized out> cache_sets = <optimized out> sets = <optimized out> i = <optimized out> count = <optimized out> __FUNCTION__ = "login_settings_read" #4 0x00007fc7a7a28278 in ssl_servername_callback (ssl=0xa0d6e0, al=<optimized out>, context=<optimized out>) at ssl-proxy-openssl.c:1144 ctx = <optimized out> proxy = <optimized out> client = 0xe95b98 host = <optimized out> other_sets = 0x0 #5 0x00007fc7a71c6162 in ?? () from /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0 No symbol table info available. #6 0x00007fc7a71b2205 in ?? () from /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0 No symbol table info available. #7 0x00007fc7a71b68c5 in ?? () from /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0 No symbol table info available. #8 0x00007fc7a71c3103 in ?? () from /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0 No symbol table info available. #9 0x00007fc7a7a289b9 in ssl_handshake (proxy=0xa185e0) at ssl-proxy-openssl.c:465 ret = <optimized out> #10 ssl_step (proxy=0xa185e0) at ssl-proxy-openssl.c:528 No locals. #11 0x00007fc7a77d6566 in io_loop_call_io (io=0xa15080) at ioloop.c:379 ioloop = 0x60d6e0 t_id = 2

#12 0x00007fc7a77d7237 in io_loop_handler_run (ioloop=<optimized out>) at ioloop-epoll.c:213 ctx = 0x9e6470 events = 0x0 event = 0x9e8030 list = 0x9f8ae0 io = <optimized out> tv = {tv_sec = 179, tv_usec = 999811} msecs = <optimized out> ret = 1 i = <optimized out> call = <optimized out> #13 0x00007fc7a77d5f78 in io_loop_run (ioloop=0x60d6e0) at ioloop.c:398 No locals. #14 0x00007fc7a77c1ee3 in master_service_run (service=0x60d590, callback=<optimized out>) at master-service.c:543 No locals. #15 0x00007fc7a7a266be in login_binary_run (binary=<optimized out>, argc=2, argv=0x60d370) at main.c:406 set_pool = 0x60da20 allow_core_dumps = <optimized out> login_socket = <optimized out> c = <optimized out> #16 0x00007fc7a7419ead in __libc_start_main () from /lib/x86_64-linux-gnu/libc.so.6 No symbol table info available. #17 0x0000000000401fd9 in _start () No symbol table info available.

Timo Sirainen

5:57 p.m.

On 7.8.2012, at 15.54, tonio@starbridge.org wrote:

...

#0 settings_parser_dup (old_ctx=0xa26920, new_pool=0x6d6f632e32) at settings-parser.c:1742 new_ctx = <optimized out> iter = <optimized out> new_link = <optimized out> links = <optimized out> key = <optimized out> value = <optimized out> i = <optimized out> parser_pool = <optimized out> __FUNCTION__ = "settings_parser_dup" #1 0x00007fc7a77c3ecc in cache_add (parser=0xa26920, output=0x7ffffe4557f0, input=0x7ffffe455790, cache=0x60ea50) at master-service-settings-cache.c:221 entry = 0xe98b90 pool = 0xe98b70 pool_size = <optimized out> entry_local_name = 0xe98b90 "pop.te.com"

I guess nobody had tried to run Dovecot with many local / remote {} blocks previously. Fixed: http://hg.dovecot.org/dovecot-2.1/rev/2815175a0ffc

tonio＠starbridge.org

6:16 p.m.

Le 07/08/2012 16:57, Timo Sirainen a écrit :

...

On 7.8.2012, at 15.54, tonio@starbridge.org wrote:

...
#0 settings_parser_dup (old_ctx=0xa26920, new_pool=0x6d6f632e32) at settings-parser.c:1742 new_ctx = <optimized out> iter = <optimized out> new_link = <optimized out> links = <optimized out> key = <optimized out> value = <optimized out> i = <optimized out> parser_pool = <optimized out> __FUNCTION__ = "settings_parser_dup" #1 0x00007fc7a77c3ecc in cache_add (parser=0xa26920, output=0x7ffffe4557f0, input=0x7ffffe455790, cache=0x60ea50) at master-service-settings-cache.c:221 entry = 0xe98b90 pool = 0xe98b70 pool_size = <optimized out> entry_local_name = 0xe98b90 "pop.te.com" I guess nobody had tried to run Dovecot with many local / remote {} blocks previously. Fixed: http://hg.dovecot.org/dovecot-2.1/rev/2815175a0ffc

Thanks Timo I will give it a try ASAP, but is it a bad thing to run dovecot with many local {} ?

Thanks again for your work ! Regards Tonio

Timo Sirainen

6:21 p.m.

On 7.8.2012, at 18.16, tonio@starbridge.org wrote:

...

I will give it a try ASAP, but is it a bad thing to run dovecot with many local {} ?

Not a bad thing, but it uses up somewhat more memory.

tonio＠starbridge.org

8 Aug 8 Aug

9:42 a.m.

Le 07/08/2012 17:21, Timo Sirainen a écrit :

...

On 7.8.2012, at 18.16, tonio@starbridge.org wrote:

...
I will give it a try ASAP, but is it a bad thing to run dovecot with many local {} ? Not a bad thing, but it uses up somewhat more memory.

Timo, 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)

Director is configured in my dovecot.conf, but I dont use it here. Proxying is made by sql request with static host.

(gdb) bt full #0 0xffffe424 in __kernel_vsyscall () No symbol table info available. #1 0xb760d941 in raise () from /lib/i386-linux-gnu/i686/cmov/libc.so.6 No symbol table info available. #2 0xb7610d72 in abort () from /lib/i386-linux-gnu/i686/cmov/libc.so.6 No symbol table info available. #3 0xb77912c0 in default_fatal_finish (type=<optimized out>, status=status@entry=0) at failures.c:191 backtrace = 0xb77de600 "<$\t" #4 0xb7791321 in i_internal_fatal_handler (ctx=0xbfd20944, format=0xb77bd4de "key not found from hash", args=0xbfd20964 "\204\nÒ¿Hv\005\båey·Wb¨m\230v\005\bù\232x·") at failures.c:649 status = 0 #5 0xb7760edd in i_panic ( format=format@entry=0xb77bd4de "key not found from hash") at failures.c:263 ctx = {type = LOG_TYPE_PANIC, exit_status = 0, timestamp = 0x0} args = 0xbfd20964 "\204\nÒ¿Hv\005\båey·Wb¨m\230v\005\bù\232x·" #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 No locals. #8 cache_add (parser=0x8b2f388, output=0xbfd209c0, input=0xbfd209c8, cache=0x8057648) at master-service-settings-cache.c:203 entry = <optimized out> pool = 0x8833fc0 pool_size = <optimized out> entry_local_name = <optimized out> #9 master_service_settings_cache_read (cache=0x8057648, input=input@entry=0xbfd20a68, dyn_parsers=dyn_parsers@entry=0x0, parser_r=parser_r@entry=0xbfd20a64, error_r=error_r@entry=0xbfd20a60) at master-service-settings-cache.c:297 output = {specific_services = 0x0, service_uses_local = 1, service_uses_remote = 0, used_local = 1, used_remote = 0} new_input = {roots = 0x804dba0, config_path = 0x0, preserve_environment = false, preserve_user = false, preserve_home = false, never_exec = false, use_sysexits = false, parse_full_config = false, module = 0x804bc38 "imap-login", service = 0x804bc33 "imap", username = 0x0, local_ip = {family = 2, u = {ip6 = {__in6_u = { __u6_addr8 = "Wb¨m", '\000' , __u6_addr16 = {25175, 28072, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {1839751767, 0, 0, 0}}}, ip4 = { s_addr = 1839751767}}}, remote_ip = {family = 2, u = {ip6 = { __in6_u = {__u6_addr8 = "[yÇc", '\000' , __u6_addr16 = {31067, 25543, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {1674017115, 0, 0, 0}}}, ip4 = { s_addr = 1674017115}}}, local_name = 0x0} set = <optimized out> __FUNCTION__ = "master_service_settings_cache_read" #10 0xb77ef48d in login_settings_read (pool=0x9801dc8, local_ip=local_ip@entry=0xbfd20b1c, remote_ip=remote_ip@entry=0xbfd20b84, local_name=local_name@entry=0x0, other_settings_r=other_settings_r@entry=0xbfd20b18) at login-settings.c:226 input = {roots = 0x804dba0, config_path = 0x0, preserve_environment = false, preserve_user = false, preserve_home = false, never_exec = false, use_sysexits = false, parse_full_config = false, module = 0x804bc38 "imap-login", service = 0x804bc33 "imap", username = 0x0, local_ip = {family = 2, u = {ip6 = {__in6_u = { __u6_addr8 = "Wb¨m", '\000' , __u6_addr16 = {25175, 28072, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {1839751767, 0, 0, 0}}}, ip4 = { s_addr = 1839751767}}}, remote_ip = {family = 2, u = {ip6 = { __in6_u = {__u6_addr8 = "[yÇc", '\000' , __u6_addr16 = {31067, 25543, 0, 0, 0, 0, 0, 0},

               __u6_addr32 = {1674017115, 0, 0, 0}}}, ip4 = {
             s_addr = 1674017115}}}, local_name = 0x0}
     error = <optimized out>
     parser = <optimized out>
     cache_sets = <optimized out>
     sets = <optimized out>
     i = <optimized out>
     count = <optimized out>
     __FUNCTION__ = "login_settings_read"

#11 0xb77ef833 in client_connected_finish (conn=0xbfd20b78) at main.c:119 client = <optimized out> proxy = <optimized out> local_ip = {family = 2, u = {ip6 = {__in6_u = { __u6_addr8 = "Wb¨m", '\000' , __u6_addr16 = { 25175, 28072, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {1839751767, 0, 0, 0}}}, ip4 = {s_addr = 1839751767}}} set = <optimized out> local_port = 993 pool = 0x9801dc8 fd_ssl = <optimized out> other_sets = <optimized out> #12 0xb778929c in master_service_listen (l=0x834d308) at master-service.c:803 service = 0x8056398

     conn = {fd = 155, listen_fd = 11, name = 0x8056585 "imaps",
       remote_ip = {family = 2, u = {ip6 = {__in6_u = {
               __u6_addr8 = "[yÇc", '\000' <repeats 11 times>,
               __u6_addr16 = {31067, 25543, 0, 0, 0, 0, 0, 0},
               __u6_addr32 = {1674017115, 0, 0, 0}}}, ip4 = {
             s_addr = 1674017115}}}, remote_port = 55451, fifo = 0,
       ssl = 1, accepted = 1}

#13 0xb77a0054 in io_loop_call_io (io=0x834d438) at ioloop.c:379 ioloop = 0x8056468 t_id = 2 #14 0xb77a0ebe in io_loop_handler_run (ioloop=ioloop@entry=0x8056468) at ioloop-epoll.c:213 ctx = 0x834c488 events = 0x0 event = 0x96af618 list = 0x834d468 io = <optimized out> tv = {tv_sec = 45, tv_usec = 831525} events_count = 0 msecs = <optimized out> ret = 1 i = <optimized out> j = <optimized out> call = <optimized out> #15 0xb779f9f0 in io_loop_run (ioloop=0x8056468) at ioloop.c:398 No locals. #16 0xb7788aae in master_service_run (service=0x8056398, callback=callback@entry=0xb77efb60 ) at master-service.c:543 No locals. #17 0xb77f0300 in login_binary_run (binary=0x804bec0, argc=argc@entry=3, argv=0x80561c0, argv@entry=0xbfd20e14) at main.c:406 set_pool = 0x8056630 allow_core_dumps = <optimized out> login_socket = 0x80561e6 "director" c = <optimized out> #18 0x08049b63 in main (argc=3, argv=0xbfd20e14) at client.c:530 No locals.

Timo Sirainen

4:41 p.m.

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)

tonio＠starbridge.org

9 Aug 9 Aug

10:15 a.m.

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.

Timo Sirainen

10:27 a.m.

On 9.8.2012, at 10.15, tonio@starbridge.org wrote:

...

...
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: .. 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== 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)

Thanks. Obviously I shouldn't free cached settings while they're still being used. :) I'll get it fixed tomorrow. For now you could work around it by increasing config_cache_size setting (default is 1M).

Timo Sirainen

10 Aug 10 Aug

2:34 a.m.

On 9.8.2012, at 10.27, Timo Sirainen wrote:

...

...
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== 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)

Thanks. Obviously I shouldn't free cached settings while they're still being used. :)

Actually it wasn't that obvious: http://hg.dovecot.org/dovecot-2.1/rev/b082b8260782 plus http://hg.dovecot.org/dovecot-2.1/rev/9d0873cefa08

tonio＠starbridge.org

13 Aug 13 Aug

6:40 p.m.

Le 10/08/2012 01:34, Timo Sirainen a écrit :

...

Actually it wasn't that obvious: http://hg.dovecot.org/dovecot-2.1/rev/b082b8260782 plus http://hg.dovecot.org/dovecot-2.1/rev/9d0873cefa08

Thanks Timo, it's working fine now

Best regards Tonio Buonaguidi

4486

Age (days ago)

4492

Last active (days ago)

List overview

10 comments

2 participants

participants (2)

Timo Sirainen
tonio＠starbridge.org