dovecot - Nov 2012 - backtrace from postgres dict

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Hi,

since I enabled ACLs I get following backtrace. It looks like that it 
happens if the ACLs had been changed only. Also, it looks like that it 
always happens 1 minute after last "dict: Info: pgsql(localhost): 
Connected to database dovecot", no matter if the user is logged in (and 
idle) or logged off. Postgres logs: "could not receive data from client: 
Connection reset by peer" and "unexpected EOF on client
connection".

Is there some TCP keep alive issue?
Postgres is using the "system default" for TCP keep alive.
I'm currently testing ACLs via telnet, so the activity with the ACL dict 
is pretty low, hence, an idle timeout would make much sense.

# ../../sbin/dovecot --version
2.1.10 (a4f02f6c0d32)

dict connect string:
connect = host=localhost dbname=db user=user



2012-11-28 10:03:39 dict: Info: pgsql(localhost): Connected to database 
dovecot
2012-11-28 10:03:39 dict: Info: pgsql(localhost): Connected to database 
dovecot
2012-11-28 10:03:39 dict: Info: pgsql(localhost): Connected to database 
dovecot

2012-11-28 10:03:58 IMAP(user) [22922]: Info: Disconnected: Logged out 
in=23 out=763

2012-11-28 10:04:41 dict: Panic: file driver-pgsql.c: line 84 
(driver_pgsql_set_state): assertion failed: (state == SQL_DB_STATE_BUSY || 
db->cur_result == NULL)

2012-11-28 10:04:41 dict: Error: Raw backtrace: 
/usr/local/dovecot-2.1.10/lib/dovecot/libdovecot.so.0(+0x4857a) 
[0x7f91f511157a] -> 
/usr/local/dovecot-2.1.10/lib/dovecot/libdovecot.so.0(+0x485c6) 
[0x7f91f51115c6] -> 
/usr/local/dovecot-2.1.10/lib/dovecot/libdovecot.so.0(i_error+0) 
[0x7f91f50e4eaf] -> dovecot2.1/dict() [0x40aa36] -> dovecot2.1/dict() 
[0x40aa91] -> dovecot2.1/dict() [0x40bed3] -> dovecot2.1/dict() [0x409504]
- -> dovecot2.1/dict(sql_db_cache_deinit+0x20) [0x408a60] -> 
dovecot2.1/dict(main+0x169) [0x405a59] -> 
/lib/libc.so.6(__libc_start_main+0xfd) [0x7f91f4b5cc8d] -> 
dovecot2.1/dict() [0x404bb9]

2012-11-28 10:04:41 dict: Fatal: master: service(dict): child 22923 killed 
with signal 6 (core not dumped)


- -- 
Steffen Kaiser
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.11 (GNU/Linux)

iQEVAwUBULXbiGoxLS8a3A9mAQI9Ywf/YItPO4fFT70HcuwCkDXgx0Sn7CEyXu2j
+1VzOu3R/TMs1rcxYJIvWiei6Nk3wXywzQl84POadJn61Yf2NuT80nMxwBsBbgio
e+0oRE9JNVSjtvX5l7kehEdUDQjqRRKyrhWG9KDlpjWidGsYh7pQg0rDtp3UwG57
HuSBMiBAZ9t9sC2DXjn9wT9vweH3gMIhc/K5U0BLF5JG/K8UAKc5QBUgezjIYzvn
KP90TJ4RoZ2vnPzmWfeIsjffRBvvC6UUgWmU02e2H9xJxzF32Nix0s8YWi7G91sH
Ei057HW5NsKNDtp6B5fYk+xCpC6ucQiwFSr/ZG+uZCAdtTd2qmf60g==tQYK
-----END PGP SIGNATURE-----

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On Wed, 28 Nov 2012, Steffen Kaiser wrote:

hmm, it seems to be more than just an idle timeout.
> since I enabled ACLs I get following backtrace. It looks like that it
happens
> if the ACLs had been changed only. Also, it looks like that it always
happens
> 1 minute after last "dict: Info: pgsql(localhost): Connected to
database
> dovecot", no matter if the user is logged in (and idle) or logged off.
> Postgres logs: "could not receive data from client: Connection reset
by peer"
> and "unexpected EOF on client connection".
>
> Is there some TCP keep alive issue?
> Postgres is using the "system default" for TCP keep alive.
> I'm currently testing ACLs via telnet, so the activity with the ACL
dict is
> pretty low, hence, an idle timeout would make much sense.
When I use this script:

( echo 1 login user pass
 	sleep 1
 	echo 2 getacl Junk
 	sleep 1
 	for a in $(seq 1 ${1-4}); do
 		echo 3-$a deleteAcl Junk user2
 		sleep 30
 		echo 3-$a SetAcl Junk user2 kxilrsc
 		sleep 30
 	done
 	echo + logout
) | nc -q1 localhost 143

I get (attached are more lines of the log):

2012-11-28 11:08:07 dict: Info: pgsql(localhost): Connected to database 
dovecot
scanning for dovecot-acl
2012-11-28 11:09:07 dict: Info: pgsql(localhost): Connected to database 
dovecot
scanning for dovecot-acl
2012-11-28 11:09:37 dict: Info: pgsql(localhost): Connected to database 
dovecot
scanning for dovecot-acl
2012-11-28 11:10:07 dict: Error: dict sql iterate failed: Not connected to 
database
2012-11-28 11:10:07 IMAP(user) [23358]: Error: acl: dict iteration failed, 
can't update dict
scanning for dovecot-acl

After that the connection is broken and I get the backtrace eventually.
> # ../../sbin/dovecot --version
> 2.1.10 (a4f02f6c0d32)
>
> dict connect string:
> connect = host=localhost dbname=db user=user
- -- 
Steffen Kaiser
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.11 (GNU/Linux)

iQEVAwUBULXqy2oxLS8a3A9mAQL4+Af+PQIzpT0/kbot90jYRYmRBA96frDlDubc
lsl9iktKGYyxLOQXRLLcUpOgzWqUvxoLtsCMlkcOG8tjyQLr2OsAufnVUL7LUH8y
iGIi8lZjfHRUQWWLgC6KG0eNOMT5PEGLB5dBcqMZxsgENjoe0SEYf3SN2bT7UxR7
N6/cbU+qnQ/IVpCCcFTtY1Nv7pHcpBwt7IQqaLTdFJ2OQBtUCFsZlkH2SArBZktC
82rHKvHkN4rsYiOhKQFyG3p7mmdmq3snUpP9fvUE+2nxsIQw2BIht8gGPMsuVoTb
DC1JjE6JGuj4z3HrEs2tYRHgnTUuUn2j28bXIp2gNDLUQzbL5DLfLQ==XUQP
-----END PGP SIGNATURE-----
-------------- next part --------------
A non-text attachment was scrubbed...
Name: acl-pg-error.log.gz
Type: application/octet-stream
Size: 1139 bytes
Desc: 
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20121128/ee569960/attachment-0004.obj>

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On Wed, 28 Nov 2012, Steffen Kaiser wrote:

with Dovecot v2.1.12 I do no get those panics anymore.
> 2012-11-28 10:04:41 dict: Panic: file driver-pgsql.c: line 84 
> (driver_pgsql_set_state): assertion failed: (state == SQL_DB_STATE_BUSY || 
> db->cur_result == NULL)
>
> 2012-11-28 10:04:41 dict: Error: Raw backtrace: 
> /usr/local/dovecot-2.1.10/lib/dovecot/libdovecot.so.0(+0x4857a) 
> [0x7f91f511157a] -> 
> /usr/local/dovecot-2.1.10/lib/dovecot/libdovecot.so.0(+0x485c6) 
> [0x7f91f51115c6] -> 
> /usr/local/dovecot-2.1.10/lib/dovecot/libdovecot.so.0(i_error+0) 
> [0x7f91f50e4eaf] -> dovecot2.1/dict() [0x40aa36] -> dovecot2.1/dict()
> [0x40aa91] -> dovecot2.1/dict() [0x40bed3] -> dovecot2.1/dict()
[0x409504] -
> -> dovecot2.1/dict(sql_db_cache_deinit+0x20) [0x408a60] -> 
> dovecot2.1/dict(main+0x169) [0x405a59] -> 
> /lib/libc.so.6(__libc_start_main+0xfd) [0x7f91f4b5cc8d] ->
dovecot2.1/dict()
> [0x404bb9]
>
> 2012-11-28 10:04:41 dict: Fatal: master: service(dict): child 22923 killed 
> with signal 6 (core not dumped)
- -- 
Steffen Kaiser
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.11 (GNU/Linux)

iQEVAwUBUNM9LGoxLS8a3A9mAQJaoQgAu5LfaqmVcdFWMF0Z+DrQvLz1xlSIP35+
cJxI7gYKh21LzpSB2iJ2DjccRUJDZRupqpIwSDLuiFYp7ORktrrO6ohieXrDM7z1
VcFO1kU2vbTYIbOloN724pSy1oFxTsec5TTi5zlL9WFjSTW2pP9oFbcSan+43ADo
gUSwm69F57GIZvOGyMSb1o83JCXRI83IajtgFtcIBuTqn6TC+zMolC2rC35ElZdM
EqkXMnGBKLNjxdp+hsro2i59bahzlIO4eigrRNFDTbiM8fInFen9BK40OnXkF2Ni
n7kh9Zx+8EDE2ayWFKaPz0hXZbbQSXcWdkfHjc/TBV9DPk2YY7BTSw==V/8J
-----END PGP SIGNATURE-----