Re: Dovecot 2.3.4 crash

[Stephan Bosch via dovecot]

Op 01/12/2018 om 00:45 schreef azu...@pobox.sk:


Citát azu...@pobox.sk:


Citát azu...@pobox.sk:


Citát Timo Sirainen :


On 29 Nov 2018, at 15.46, azu...@pobox.sk wrote:


Hi,

is this a know problem? Newest Dovecot 2.3.4 package from 
repo.dovecot.org , Debian Stretch (fully upgraded).




Nov 29 14:25:11 server00 dovecot: lmtp(16854): Panic: file 
ostream-dot.c: line 208 (o_stream_dot_sendv): assertion failed: 
((size_t)ret == sent + added)


Is this proxying LMTP traffic?





Yes, it is. The main server is, currently, doing standard 
IMAP/POP3/LMTP for some clients and also proxying IMAP/POP3/LMTP for 
other clients (proxying to other servers). But this one error is 
related to one message which is stucked in postfix queue and cannot 
be delivered - the error appears everytime i do 'postfix flush' 
(error in postfix queue is 'lost connection with 
[private/dovecot-lmtp] while sending 
end of data -- message may be sent more than once').


There are no errors logged on proxy backend side.
Just to clarify this - that one message is to be proxied to other 
server.


Anything new to this? Thank you.


Fix is included in 2.3.5.

Regards,

Stephan.

Re: Dovecot 2.3.4 crash

[Stephan Bosch]

Op 04/12/2018 om 15:58 schreef Aki Tuomi:

On 04 December 2018 at 13:23 Guillaume via dovecot  wrote:


A full example with dovecot debug symbols activated (note since I have activate 
valgrind, no more segfault it’s normal I presume ):


Hi!

We believe this is fixed with 
https://github.com/dovecot/core/commit/3c5101ffdd2a8115e03ed7180d53578765dea4c9.patch


Internally tracked as DOV-2826.

Regards,

Stephan.

Re: Dovecot 2.3.4 crash

[Guillaume via dovecot]

OK I patched your Debian package just with this patch and now it works :) So 
you find the problem thanks !!!

> Le 4 déc. 2018 à 15:58, Aki Tuomi  a écrit :
> Hi!
> 
> We believe this is fixed with 
> https://github.com/dovecot/core/commit/3c5101ffdd2a8115e03ed7180d53578765dea4c9.patch
> 
> Aki

Re: Dovecot 2.3.4 crash

[Aki Tuomi]

> On 04 December 2018 at 13:23 Guillaume via dovecot  
> wrote:
> 
> 
> A full example with dovecot debug symbols activated (note since I have 
> activate valgrind, no more segfault it’s normal I presume ):
> 

Hi!

We believe this is fixed with 
https://github.com/dovecot/core/commit/3c5101ffdd2a8115e03ed7180d53578765dea4c9.patch

Aki

Re: Dovecot 2.3.4 crash

[Guillaume via dovecot]

Another example with dovecot debug symbols activated (note since I have 
activate valgrind, no more segfault it’s normal I presume ):

Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071== Invalid read of size 8
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3053== Invalid read of size 8
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3057== Invalid read of size 8
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3057==at 0x6E8767F: 
mysql_close (mariadb_lib.c:1916)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3057==by 0x14768B: 
driver_sqlpool_disconnect (driver-sqlpool.c:590)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3057==by 0x13D0B4: 
db_sql_unref (db-sql.c:128)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3057==by 0x1359D8: 
userdb_deinit (userdb.c:191)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3057==by 0x119C88: 
auth_deinit (auth.c:335)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3057==by 0x119C88: 
auths_deinit (auth.c:433)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3066== Invalid read of size 8
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3049== Invalid read of size 8
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==at 0x6E8767F: 
mysql_close (mariadb_lib.c:1916)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==by 0x14768B: 
driver_sqlpool_disconnect (driver-sqlpool.c:590)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==by 0x13D0B4: 
db_sql_unref (db-sql.c:128)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==by 0x1359D8: 
userdb_deinit (userdb.c:191)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==by 0x119C88: 
auth_deinit (auth.c:335)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==by 0x119C88: 
auths_deinit (auth.c:433)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==by 0x1187FF: 
main_deinit (main.c:271)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==by 0x1187FF: main 
(main.c:398)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==  Address 0x66e3870 is 0 
bytes inside a block of size 120 free'd
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==at 0x4C2CDDB: free 
(vg_replace_malloc.c:530)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==by 0x6E877FE: 
mysql_close (mariadb_lib.c:1947)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==by 0x14768B: 
driver_sqlpool_disconnect (driver-sqlpool.c:590)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==by 0x13D0B4: 
db_sql_unref (db-sql.c:128)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==by 0x1318C1: 
passdb_deinit (passdb.c:266)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==by 0x119C68: 
auth_deinit (auth.c:333)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==by 0x119C68: 
auths_deinit (auth.c:433)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==by 0x1187FF: 
main_deinit (main.c:271)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==by 0x1187FF: main 
(main.c:398)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==  Block was alloc'd at
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==at 0x4C2DBC5: calloc 
(vg_replace_malloc.c:711)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==by 0x6E8250A: 
mysql_init (mariadb_lib.c:996)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==by 0x6C60837: 
driver_mysql_connect (driver-mysql.c:93)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==by 0x146FE4: 
driver_sqlpool_connect (driver-sqlpool.c:574)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==by 0x13D10C: 
db_sql_connect (db-sql.c:140)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==by 0x1348B0: 
passdb_sql_init (passdb-sql.c:286)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==by 0x131818: 
passdb_init (passdb.c:248)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==by 0x1195D3: 
auth_passdb_init.isra.8 (auth.c:306)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==by 0x119AFC: 
auth_init (auth.c:320)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==by 0x119AFC: 
auths_init (auth.c:425)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==by 0x118786: 
main_init (main.c:245)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==by 0x118786: main 
(main.c:394)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3071==
...

Dec  4 12:09:40  dovecot: auth-worker: Error: ==3066==
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3066== Invalid write of size 8
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3066==at 0x6E87636: memset 
(string3.h:90)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3066==by 0x6E87636: 
ma_clear_session_state (mariadb_lib.c:1908)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3066==by 0x6E8777D: 
mysql_close (mariadb_lib.c:1936)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3066==by 0x14768B: 
driver_sqlpool_disconnect (driver-sqlpool.c:590)
Dec  4 12:09:40  dovecot: auth-worker: Error: ==3066==by 

Re: Dovecot 2.3.4 crash

[Guillaume via dovecot]

Hi !

Yes it happens every 2 to 5 minutes so no problem in reproducing.

I made the change with valgrind, I have now this in my log :

Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2436== Invalid read of 
size 8
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2393== Invalid read of 
size 8
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2476== Invalid read of 
size 8
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2431== Invalid read of 
size 8
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2468== Invalid read of 
size 8
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2476==at 0x6E8767F: 
mysql_close (mariadb_lib.c:1916)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2476==by 0x14768B: ??? 
(in /usr/lib/dovecot/auth)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2476==by 0x13D0B4: 
db_sql_unref (in /usr/lib/dovecot/auth)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2476==by 0x1359D8: 
userdb_deinit (in /usr/lib/dovecot/auth)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2476==by 0x119C88: 
auths_deinit (in /usr/lib/dovecot/auth)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2476==by 0x1187FF: 
main (in /usr/lib/dovecot/auth)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2476==  Address 0x66e3870 
is 0 bytes inside a block of size 120 free'd
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2476==at 0x4C2CDDB: 
free (vg_replace_malloc.c:530)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2476==by 0x6E877FE: 
mysql_close (mariadb_lib.c:1947)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2476==by 0x14768B: ??? 
(in /usr/lib/dovecot/auth)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2436==at 0x6E8767F: 
mysql_close (mariadb_lib.c:1916)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2436==by 0x14768B: ??? 
(in /usr/lib/dovecot/auth)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2476==by 0x13D0B4: 
db_sql_unref (in /usr/lib/dovecot/auth)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2476==by 0x1318C1: 
passdb_deinit (in /usr/lib/dovecot/auth)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2436==by 0x13D0B4: 
db_sql_unref (in /usr/lib/dovecot/auth)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2476==by 0x119C68: 
auths_deinit (in /usr/lib/dovecot/auth)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2436==by 0x1359D8: 
userdb_deinit (in /usr/lib/dovecot/auth)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2476==by 0x1187FF: 
main (in /usr/lib/dovecot/auth)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2436==by 0x119C88: 
auths_deinit (in /usr/lib/dovecot/auth)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2476==  Block was alloc'd 
at
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2436==by 0x1187FF: 
main (in /usr/lib/dovecot/auth)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2476==at 0x4C2DBC5: 
calloc (vg_replace_malloc.c:711)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2436==  Address 0x66e3870 
is 0 bytes inside a block of size 120 free'd
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2436==at 0x4C2CDDB: 
free (vg_replace_malloc.c:530)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2476==by 0x6E8250A: 
mysql_init (mariadb_lib.c:996)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2476==by 0x6C60837: 
??? (in /usr/lib/dovecot/modules/libdriver_mysql.so)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2436==by 0x6E877FE: 
mysql_close (mariadb_lib.c:1947)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2476==by 0x146FE4: ??? 
(in /usr/lib/dovecot/auth)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2436==by 0x14768B: ??? 
(in /usr/lib/dovecot/auth)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2476==by 0x13D10C: 
db_sql_connect (in /usr/lib/dovecot/auth)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2436==by 0x13D0B4: 
db_sql_unref (in /usr/lib/dovecot/auth)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2476==by 0x1348B0: ??? 
(in /usr/lib/dovecot/auth)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2436==by 0x1318C1: 
passdb_deinit (in /usr/lib/dovecot/auth)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2476==by 0x131818: 
passdb_init (in /usr/lib/dovecot/auth)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2436==by 0x119C68: 
auths_deinit (in /usr/lib/dovecot/auth)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2476==by 0x1195D3: ??? 
(in /usr/lib/dovecot/auth)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2436==by 0x1187FF: 
main (in /usr/lib/dovecot/auth)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2476==by 0x119AFC: 
auths_init (in /usr/lib/dovecot/auth)
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2436==  Block was alloc'd 
at
Dec  4 12:00:27 x dovecot: auth-worker: Error: ==2476==

Re: Dovecot 2.3.4 crash

[Timo Sirainen]

On 2 Dec 2018, at 22.22, Guillaume via dovecot  wrote:
> 
> I also have this kind of segfault since the update :
> 
> Dec  2 21:12:11 xxx dovecot: auth-worker: Error: *** Error in 
> `dovecot/auth': double free or corruption (fasttop): 0x55573bb99f70

Is this easy to reproduce? Can you try with valgrind? It will slow down the 
logins a bit though.

service auth-worker {
  executable = /usr/bin/valgrind -q --vgdb=no /usr/lib/dovecot/auth -w
}

At least one good thing about this crash is that it seems to happen only at 
deinit, so it's not impacting users.

Re: Dovecot 2.3.4 crash

[azurit]

Citát azu...@pobox.sk:


Citát azu...@pobox.sk:


Citát Timo Sirainen :


On 29 Nov 2018, at 15.46, azu...@pobox.sk wrote:


Hi,

is this a know problem? Newest Dovecot 2.3.4 package from  
repo.dovecot.org , Debian Stretch (fully upgraded).




Nov 29 14:25:11 server00 dovecot: lmtp(16854): Panic: file  
ostream-dot.c: line 208 (o_stream_dot_sendv): assertion failed:  
((size_t)ret == sent + added)


Is this proxying LMTP traffic?





Yes, it is. The main server is, currently, doing standard  
IMAP/POP3/LMTP for some clients and also proxying IMAP/POP3/LMTP  
for other clients (proxying to other servers). But this one error  
is related to one message which is stucked in postfix queue and  
cannot be delivered - the error appears everytime i do 'postfix  
flush' (error in postfix queue is 'lost connection with  
[private/dovecot-lmtp] while  
sending end of data -- message may be sent more than once').


There are no errors logged on proxy backend side.





Just to clarify this - that one message is to be proxied to other server.





Anything new to this? Thank you.

azur

Re: Dovecot 2.3.4 crash

[azurit]

Citát azu...@pobox.sk:


Citát Timo Sirainen :


On 29 Nov 2018, at 15.46, azu...@pobox.sk wrote:


Hi,

is this a know problem? Newest Dovecot 2.3.4 package from  
repo.dovecot.org , Debian Stretch (fully upgraded).




Nov 29 14:25:11 server00 dovecot: lmtp(16854): Panic: file  
ostream-dot.c: line 208 (o_stream_dot_sendv): assertion failed:  
((size_t)ret == sent + added)


Is this proxying LMTP traffic?





Yes, it is. The main server is, currently, doing standard  
IMAP/POP3/LMTP for some clients and also proxying IMAP/POP3/LMTP for  
other clients (proxying to other servers). But this one error is  
related to one message which is stucked in postfix queue and cannot  
be delivered - the error appears everytime i do 'postfix flush'  
(error in postfix queue is 'lost connection with  
[private/dovecot-lmtp] while sending  
end of data -- message may be sent more than once').


There are no errors logged on proxy backend side.





Just to clarify this - that one message is to be proxied to other server.

Re: Dovecot 2.3.4 crash

[azurit]

Citát Timo Sirainen :


On 29 Nov 2018, at 15.46, azu...@pobox.sk wrote:


Hi,

is this a know problem? Newest Dovecot 2.3.4 package from  
repo.dovecot.org , Debian Stretch (fully upgraded).




Nov 29 14:25:11 server00 dovecot: lmtp(16854): Panic: file  
ostream-dot.c: line 208 (o_stream_dot_sendv): assertion failed:  
((size_t)ret == sent + added)


Is this proxying LMTP traffic?





Yes, it is. The main server is, currently, doing standard  
IMAP/POP3/LMTP for some clients and also proxying IMAP/POP3/LMTP for  
other clients (proxying to other servers). But this one error is  
related to one message which is stucked in postfix queue and cannot be  
delivered - the error appears everytime i do 'postfix flush' (error in  
postfix queue is 'lost connection with  
[private/dovecot-lmtp] while sending  
end of data -- message may be sent more than once').


There are no errors logged on proxy backend side.





dovecot/lmtp [local DATA](_start+0x2a) [0x565287c310ca]


Based on this I was thinking it wouldn't be. But this apparently  
happens only with sending SMTP/LMTP traffic with SSL. So do you  
think it's SSL-related with you also?  
https://www.dovecot.org/pipermail/dovecot/2018-November/113532.html  




We are, currently, not using SSL while proxying traffic.

Re: Dovecot 2.3.4 crash

[Timo Sirainen]

On 29 Nov 2018, at 15.46, azu...@pobox.sk wrote:
> 
> Hi,
> 
> is this a know problem? Newest Dovecot 2.3.4 package from repo.dovecot.org , 
> Debian Stretch (fully upgraded).
> 
> 
> 
> Nov 29 14:25:11 server00 dovecot: lmtp(16854): Panic: file ostream-dot.c: 
> line 208 (o_stream_dot_sendv): assertion failed: ((size_t)ret == sent + added)

Is this proxying LMTP traffic?

> dovecot/lmtp [local DATA](_start+0x2a) [0x565287c310ca]

Based on this I was thinking it wouldn't be. But this apparently happens only 
with sending SMTP/LMTP traffic with SSL. So do you think it's SSL-related with 
you also? https://www.dovecot.org/pipermail/dovecot/2018-November/113532.html 

Dovecot 2.3.4 crash

[azurit]

Hi,

is this a know problem? Newest Dovecot 2.3.4 package from  
repo.dovecot.org , Debian Stretch (fully upgraded).




Nov 29 14:25:11 server00 dovecot: lmtp(16854): Panic: file  
ostream-dot.c: line 208 (o_stream_dot_sendv): assertion failed:  
((size_t)ret == sent + added)



Nov 29 14:25:11 server00 dovecot: lmtp(16854): Error: Raw backtrace:  
/usr/lib/dovecot/libdovecot.so.0(+0xd25e1) [0x7fa5f7b655e1] ->  
/usr/lib/dovecot/libdovecot.so.0(+0xd2681) [0x7
fa5f7b65681] -> /usr/lib/dovecot/libdovecot.so.0(i_fatal+0)  
[0x7fa5f7acd093] -> /usr/lib/dovecot/libdovecot.so.0(+0xbb97b)  
[0x7fa5f7b4e97b] -> /usr/lib/dovecot/libdovecot.so.0(+0x
fa4ae) [0x7fa5f7b8d4ae] ->  
/usr/lib/dovecot/libdovecot.so.0(o_stream_sendv+0x2e) [0x7fa5f7b8da3e]  
-> /usr/lib/dovecot/libdovecot.so.0(io_stream_copy+0x52)  
[0x7fa5f7b8e512] -> /usr
/lib/dovecot/libdovecot.so.0(o_stream_send_istream+0x58)  
[0x7fa5f7b8e008] ->  
/usr/lib/dovecot/libdovecot.so.0(smtp_client_command_send_more+0x1b1)  
[0x7fa5f7ad7351] -> /usr/lib/dov
ecot/libdovecot.so.0(+0x4a096) [0x7fa5f7add096] ->  
/usr/lib/dovecot/libdovecot.so.0(+0xfd0c3) [0x7fa5f7b900c3] ->  
/usr/lib/dovecot/libdovecot.so.0(io_loop_call_io+0x75) [0x7fa5f7b
7e5d5] ->  
/usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0x109)  
[0x7fa5f7b7ffd9] ->  
/usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x56)  
[0x7fa5f7b7e6e6] -> /
usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x38) [0x7fa5f7b7e8f8] ->  
/usr/lib/dovecot/libdovecot.so.0(master_service_run+0x13)  
[0x7fa5f7af2d43] -> dovecot/lmtp [local DATA](main+
0x240) [0x565287c30f70] ->  
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf1)  
[0x7fa5f77142e1] -> dovecot/lmtp [local DATA](_start+0x2a)  
[0x565287c310ca]



Nov 29 14:25:11 server00 dovecot: lmtp(16854): Fatal: master:  
service(lmtp): child 16854 killed with signal 6 (core dumps disabled -  
https://dovecot.org/bugreport.html#coredumps)





azur