[Dovecot] dspam plugin
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
Hey everyone.. been struggling with building a mailserver and i'm almost done. One of the last pieces is integrating dovecot with dspam so that I'm users can train their spam filters easily (sieve filtering is the last piece left.. that should be interesting.. lol)
Anyway, I think i found an issue with memory allocation, and I'm not sure if its due to changes to the code base or if its a 64 bit memory issue.
When i try to move a message into or out of the spam folder, it fails, and with debugging on, there are strange entries in the syslog.
Added a few more debugging statements, and I get the following showing up:
Apr 11 00:04:41 uberserver imap: found signature 443b336a271581061887518 Apr 11 00:04:41 uberserver imap: working with signature (<E4>Z Apr 11 00:04:41 uberserver imap: in call dspam Apr 11 00:04:41 uberserver imap: /usr/bin/dspam --source=error --stdout
- --class=spam --signature=(<E4>Z Apr 11 00:04:41 uberserver dspam[1361]: Unable to determine the destination user Apr 11 00:04:41 uberserver dspam[1361]: DSPAM agent misconfigured: aborting
The line with the correct signature showing up is simply outputing 'signature' after:
signature = mail_get_first_header(mail, SIGHEADERLINE);The 'working with signature' that shows the corrupted signature is right before call_dspam is called, and it outputs siglist->sig:
... syslog(LOG_INFO, "working with signature %s ", siglist->sig ); if ((*enh_error = call_dspam (siglist->sig, is_spam))) { ...
This leads me to believe that there's a problem with:
list_append(listpool, &siglist)->sig = p_strdup(listpool, signature);but I'm really not sure how dovecot deals with allocating pooled memory, as that's what it appears to be doing.
I'm not sure what information might be useful to anyone in helping me look into this and the searches i've been able to do have been unsuccessful.
Thanks in advance,
Ryan
PGP Fingerprint - E15C CC7D 5830 AB8A C2AE 5C5E 80D8 6B63 D40B 015C
-----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.1 (GNU/Linux)
iD8DBQFEOz9YgNhrY9QLAVwRAkK9AJ9Tf5eDFtNs2oYG6BpNxPNUUxZ3VwCfRhYo ify05xCWACczHUHvOBFyQYg= =en2A -----END PGP SIGNATURE-----
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
Sorry to reply to my own message, but I'm trying to get a handle on why the dspam plugin is not behaving nicely.
I've isolated the problem to one line of code, but I'm not really sure why its breaking, any light anyone can shed on this would be really appreciated. I still have yet to determine if 64bit could have anything to do with it (unlikely, since the code looks similar to other dovecot pool allocations) or if the plugin is somehow not compatiable with the CVS version.
I changed the following line of code:
202 list_append(listpool, &siglist)->sig = p_strdup(listpool, signature);
to :
list_append(listpool, &siglist);
siglist->sig = p_strdup(listpool, signature);#ifdef DEBUG syslog(LOG_INFO, "stored %s into siglist, value is %s ", signature, siglist->sig ); #endif
And I'm seeing the following in my syslog:
Apr 11 14:53:50 uberserver imap: stored 443b702a6341804284693 into siglist, value is <F8><E3>Z Apr 11 14:53:50 uberserver imap: working with signature <F8><E3>Z Apr 11 14:53:50 uberserver imap: in call dspam Apr 11 14:53:50 uberserver imap: /usr/bin/dspam --source=error --stdout
- --class=spam --signature=<F8><E3>Z Apr 11 14:53:50 uberserver dspam[18204]: Unable to determine the destination user Apr 11 14:53:50 uberserver dspam[18204]: DSPAM agent misconfigured: aborting
I don't really see anything wrong in the function that appends to the linked list (list_append) so I'm kinda stuck at this point. Everything should be fairly standard, as I used the configure parameters from the gentoo install and added --without-deliver as I'm using the dovecot LDA as well.
My configure command in case it helps:
./configure --prefix=/usr --host=x86_64-pc-linux-gnu
- --mandir=/usr/share/man --infodir=/usr/share/info --datadir=/usr/share
- --sysconfdir=/etc --localstatedir=/var/lib --localstatedir=/var
- --disable-debug --enable-ipv6 --without-gssapi --without-ldap --with-mysql
- --with-pam --with-pop3d --without-pgsql --without-vpopmail
- --with-ssl=openssl --libdir=/usr/lib64 --build=x86_64-pc-linux-gnu
- --without-deliver
Thanks again, going to keep digging into this and will report back if i find anything.
Ryan
On Tue, April 11, 2006 12:32 am, Ryan Kolak said:
Hey everyone.. been struggling with building a mailserver and i'm almost done. One of the last pieces is integrating dovecot with dspam so that I'm users can train their spam filters easily (sieve filtering is the last piece left.. that should be interesting.. lol)
Anyway, I think i found an issue with memory allocation, and I'm not sure if its due to changes to the code base or if its a 64 bit memory issue.
When i try to move a message into or out of the spam folder, it fails, and with debugging on, there are strange entries in the syslog.
Added a few more debugging statements, and I get the following showing up:
Apr 11 00:04:41 uberserver imap: found signature 443b336a271581061887518 Apr 11 00:04:41 uberserver imap: working with signature (<E4>Z Apr 11 00:04:41 uberserver imap: in call dspam Apr 11 00:04:41 uberserver imap: /usr/bin/dspam --source=error --stdout
- --class=spam --signature=(<E4>Z Apr 11 00:04:41 uberserver dspam[1361]: Unable to determine the destination user Apr 11 00:04:41 uberserver dspam[1361]: DSPAM agent misconfigured: aborting
The line with the correct signature showing up is simply outputing 'signature' after:
signature = mail_get_first_header(mail, SIGHEADERLINE);The 'working with signature' that shows the corrupted signature is right before call_dspam is called, and it outputs siglist->sig:
... syslog(LOG_INFO, "working with signature %s ", siglist->sig ); if ((*enh_error = call_dspam (siglist->sig, is_spam))) { ...
This leads me to believe that there's a problem with:
list_append(listpool, &siglist)->sig = p_strdup(listpool, signature);but I'm really not sure how dovecot deals with allocating pooled memory, as that's what it appears to be doing.
I'm not sure what information might be useful to anyone in helping me look into this and the searches i've been able to do have been unsuccessful.
Thanks in advance,
Ryan
PGP Fingerprint - E15C CC7D 5830 AB8A C2AE 5C5E 80D8 6B63 D40B 015C
PGP Fingerprint - E15C CC7D 5830 AB8A C2AE 5C5E 80D8 6B63 D40B 015C
-----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.1 (GNU/Linux)
iD8DBQFEPDLXgNhrY9QLAVwRAqcRAKDJsP33B+bS7wl6NLei/lgdJW24rACeIIKQ 7pgKCSByEz79wYhSF5mxbYo= =QxCm -----END PGP SIGNATURE-----
On Tue, 2006-04-11 at 17:51 -0500, Ryan Kolak wrote:
I've isolated the problem to one line of code, but I'm not really sure why its breaking, any light anyone can shed on this would be really appreciated. I still have yet to determine if 64bit could have anything to do with it (unlikely, since the code looks similar to other dovecot pool allocations) or if the plugin is somehow not compatiable with the CVS version.
You compiled it against that version, so the latter is highly unlikely. If you're compiling the plugin against a different version and trying to use the binary, there's a chance that is the problem, but other than that...
I changed the following line of code:
202 list_append(listpool, &siglist)->sig = p_strdup(listpool, signature);
to :
list_append(listpool, &siglist); siglist->sig = p_strdup(listpool, signature);#ifdef DEBUG syslog(LOG_INFO, "stored %s into siglist, value is %s ", signature, siglist->sig ); #endif
And I'm seeing the following in my syslog:
Apr 11 14:53:50 uberserver imap: stored 443b702a6341804284693 into siglist, value is <F8><E3>Z Apr 11 14:53:50 uberserver imap: working with signature <F8><E3>Z Apr 11 14:53:50 uberserver imap: in call dspam Apr 11 14:53:50 uberserver imap: /usr/bin/dspam --source=error --stdout
- --class=spam --signature=<F8><E3>Z
That's very odd. I have no idea what is causing this. Can you run in valgrind (do you have valgrind for 64 bits?)
johannes
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
valgrind is new to me, think i ran it right:
# valgrind --show-reachable=yes --leak-check=full /usr/sbin/dovecot
found a small handful of leaks on startup, none of which look like anything directly related.. There's one more leak when the first time i load a page via squirrelmail (in the login process), but nothing after that until i kill dovecot. the full output is at the bottom if its useful at all.
I don't really see how this could be happening as the list allocation seems straightforward. I could add in some debug syslog statements in there but i doubt that would be useful. I'd like to step into the code a bit more but i'm at a loss on what to do next. I'm open to suggestions, and fairly capable too.
Thanks again for the help,
Ryan
==30557== Memcheck, a memory error detector. ==30557== Copyright (C) 2002-2005, and GNU GPL'd, by Julian Seward et al. ==30557== Using LibVEX rev 1471, a library for dynamic binary translation. ==30557== Copyright (C) 2004-2005, and GNU GPL'd, by OpenWorks LLP. ==30557== Using valgrind-3.1.0, a dynamic binary instrumentation framework. ==30557== Copyright (C) 2000-2005, and GNU GPL'd, by Julian Seward et al. ==30557== For more details, rerun with: -v ==30557== ==30557== ==30557== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 5 from 1) ==30557== malloc/free: in use at exit: 25,668 bytes in 15 blocks. ==30557== malloc/free: 83 allocs, 68 frees, 39,234 bytes allocated. ==30557== For counts of detected errors, rerun with: -v ==30557== searching for pointers to 15 not-freed blocks. ==30557== checked 97,824 bytes. ==30557== ==30557== 292 (52 direct, 240 indirect) bytes in 1 blocks are definitely lost in loss record 1 of 6 ==30557== at 0x4A18AFE: malloc (in /usr/lib64/valgrind/amd64-linux/vgpreload_ memcheck.so) ==30557== by 0x4BE27EF: (within /lib64/libc-2.3.5.so) ==30557== by 0x4BE309E: __nss_database_lookup (in /lib64/libc-2.3.5.so) ==30557== by 0x4E4549F: ??? ==30557== by 0x4E463CB: ??? ==30557== by 0x4BA7BE4: getpwnam_r (in /lib64/libc-2.3.5.so) ==30557== by 0x4BA7721: getpwnam (in /lib64/libc-2.3.5.so) ==30557== by 0x40860E: settings_verify (master-settings.c:418) ==30557== by 0x409A66: master_settings_read (master-settings.c:1188) ==30557== by 0x407E82: main (main.c:767) ==30557== ==30557== ==30557== 80 bytes in 5 blocks are indirectly lost in loss record 2 of 6 ==30557== at 0x4A18AFE: malloc (in /usr/lib64/valgrind/amd64-linux/vgpreload_memcheck.so) ==30557== by 0x4BE23CF: __nss_lookup_function (in /lib64/libc-2.3.5.so) ==30557== by 0x4E454BA: ??? ==30557== by 0x4E463CB: ??? ==30557== by 0x4BA7BE4: getpwnam_r (in /lib64/libc-2.3.5.so) ==30557== by 0x4BA7721: getpwnam (in /lib64/libc-2.3.5.so) ==30557== by 0x40860E: settings_verify (master-settings.c:418) ==30557== by 0x409A66: master_settings_read (master-settings.c:1188) ==30557== by 0x407E82: main (main.c:767) ==30557== ==30557== ==30557== 160 bytes in 5 blocks are indirectly lost in loss record 3 of 6 ==30557== at 0x4A18AFE: malloc (in /usr/lib64/valgrind/amd64-linux/vgpreload_memcheck.so) ==30557== by 0x4BD2159: tsearch (in /lib64/libc-2.3.5.so) ==30557== by 0x4BE2389: __nss_lookup_function (in /lib64/libc-2.3.5.so) ==30557== by 0x4E454BA: ??? ==30557== by 0x4E463CB: ??? ==30557== by 0x4BA7BE4: getpwnam_r (in /lib64/libc-2.3.5.so) ==30557== by 0x4BA7721: getpwnam (in /lib64/libc-2.3.5.so) ==30557== by 0x40860E: settings_verify (master-settings.c:418) ==30557== by 0x409A66: master_settings_read (master-settings.c:1188) ==30557== by 0x407E82: main (main.c:767) ==30557== ==30557== ==30557== 776 bytes in 1 blocks are still reachable in loss record 4 of 6 ==30557== at 0x4A1A181: calloc (in /usr/lib64/valgrind/amd64-linux/vgpreload_memcheck.so) ==30557== by 0x40B611: t_push (data-stack.c:91) ==30557== by 0x40F846: lib_init (lib.c:24) ==30557== by 0x407DD5: main (main.c:715) ==30557== ==30557== ==30557== 8,192 bytes in 2 blocks are still reachable in loss record 5 of 6 ==30557== at 0x4A1A181: calloc (in /usr/lib64/valgrind/amd64-linux/vgpreload_memcheck.so) ==30557== by 0x40FEA7: block_alloc (mempool-alloconly.c:171) ==30557== by 0x40FFF4: pool_alloconly_create (mempool-alloconly.c:88) ==30557== by 0x40A042: master_settings_init (master-settings.c:1406) ==30557== by 0x407E6D: main (main.c:766) ==30557== ==30557== ==30557== 16,408 bytes in 1 blocks are still reachable in loss record 6 of 6 ==30557== at 0x4A18AFE: malloc (in /usr/lib64/valgrind/amd64-linux/vgpreload_memcheck.so) ==30557== by 0x40B497: mem_block_alloc (data-stack.c:190) ==30557== by 0x40B4FA: data_stack_init (data-stack.c:360) ==30557== by 0x40F846: lib_init (lib.c:24) ==30557== by 0x407DD5: main (main.c:715) ==30557== ==30557== LEAK SUMMARY: ==30557== definitely lost: 52 bytes in 1 blocks. ==30557== indirectly lost: 240 bytes in 10 blocks. ==30557== possibly lost: 0 bytes in 0 blocks. ==30557== still reachable: 25,376 bytes in 4 blocks. ==30557== suppressed: 0 bytes in 0 blocks.
After logging in: ==30561== Syscall param write(buf) points to uninitialised byte(s) ==30561== at 0x4BC7D72: write (in /lib64/libc-2.3.5.so) ==30561== by 0x411CC1: o_stream_writev (ostream-file.c:131) ==30561== by 0x4124BC: _sendv (ostream-file.c:441) ==30561== by 0x411977: o_stream_sendv (ostream.c:124) ==30561== by 0x4119A9: o_stream_send (ostream.c:107) ==30561== by 0x405041: auth_master_callback (login-process.c:100) ==30561== by 0x40342C: auth_process_input (auth-process.c:120) ==30561== by 0x40F755: io_loop_handler_run (ioloop-poll.c:203) ==30561== by 0x40EBD9: io_loop_run (ioloop.c:274) ==30561== by 0x4082E5: main (main.c:816)
After killing pid 30561, there were three more leaks from settings_verify in master-settings.c which shouldn't have anything to do with this.
On Tue, April 11, 2006 7:41 pm, Johannes Berg said:
On Tue, 2006-04-11 at 17:51 -0500, Ryan Kolak wrote:
I've isolated the problem to one line of code, but I'm not really sure why its breaking, any light anyone can shed on this would be really appreciated. I still have yet to determine if 64bit could have anything to do with it (unlikely, since the code looks similar to other dovecot pool allocations) or if the plugin is somehow not compatiable with the CVS version.
You compiled it against that version, so the latter is highly unlikely. If you're compiling the plugin against a different version and trying to use the binary, there's a chance that is the problem, but other than that...
I changed the following line of code:
202 list_append(listpool, &siglist)->sig = p_strdup(listpool, signature);
to :
list_append(listpool, &siglist); siglist->sig = p_strdup(listpool, signature);#ifdef DEBUG syslog(LOG_INFO, "stored %s into siglist, value is %s ", signature, siglist->sig ); #endif
And I'm seeing the following in my syslog:
Apr 11 14:53:50 uberserver imap: stored 443b702a6341804284693 into siglist, value is <F8><E3>Z Apr 11 14:53:50 uberserver imap: working with signature <F8><E3>Z Apr 11 14:53:50 uberserver imap: in call dspam Apr 11 14:53:50 uberserver imap: /usr/bin/dspam --source=error --stdout
- --class=spam --signature=<F8><E3>Z
That's very odd. I have no idea what is causing this. Can you run in valgrind (do you have valgrind for 64 bits?)
johannes
PGP Fingerprint - E15C CC7D 5830 AB8A C2AE 5C5E 80D8 6B63 D40B 015C
-----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.1 (GNU/Linux)
iD8DBQFEPHCrgNhrY9QLAVwRAizdAJ40/8Bvrj3NBwuJV8G6djgE5e0I+wCfREcW pcQkqBfmPjEpyyWJHVt2YI0= =Rl/T -----END PGP SIGNATURE-----
On Tue, 2006-04-11 at 22:14 -0500, Ryan Kolak wrote:
found a small handful of leaks on startup, none of which look like anything directly related.. There's one more leak when the first time i load a page via squirrelmail (in the login process), but nothing after that until i kill dovecot. the full output is at the bottom if its useful at all.
There's definitely a small one-time leak when the plugin is loaded which valgrind should've shown. Are you sure that you actually used the plugin by moving some mail between normal and spam?
johannes
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
I tracked down the problem. Not really sure what's causing it or how to fix it but I managed to work around the issue. Also ran into a couple other problems that are similar to some other recent issues on this list. Sorry for the longish email, but i'm hoping that this will help some other people as well.
In trying to determine if the memory corruption was in creating the string or in storing it into our linked arrary, i first stored the result from p_strdup into a variable, inspected the results, and then had the normal line of code that called p_strdup again.
For whatever reason, the second call to p_strdup succeeds and does The Right Thing(tm). I'm not sure if there's an issue with allocating or setting up the pool.
I'm fairly new to dovecot so I'm not sure of how it handles connections, but I think i'm ok with allocating the extra string as i'm under the impression that each imap session is a forked process so there shouldn't be any long term leaks.
So, in my working plugin, i have changed:
list_append(listpool, &siglist)->sig = p_strdup(listpool, signature);
to:
list_append(listpool, &siglist); p_strdup(listpool, signature); siglist->sig = p_strdup(listpool, signature);
as long as it works.. i'm not going to complain too much!
A couple other points: valgrind has never raised any issues with anything in the plugin. I even tried running it with trace-children enabled. I'm running gentoo and valgrind is ~amd64 (not marked as stable) so perhaps it has some 64 bit issues as well or wasn't able to detect anything.
Also, I was still getting errors once the plugin was getting far enough to call dspam with a valid signature. It was complaining that it couldn't determine the user. Learned a little bit more about the dspam design. Apparently, for the plugin to work as is, the user that's calling dspam needs to exist in the virtual_uids table.
dspam apparently always needs to know what user its working with. However, the plugin doesn't have any fuctionality for determining this from the email. Thankfully, the dspam signature can be written to the email in the form of <uid>,<signature> if MySQLUIDInSignature is set to on in the dpsam.conf file.
Even though dspam can determine the user from the signature, it still needs to startup as a valid user. If the user is notspecified on the command line with the --user parameter, dspam uses the user that invoked dspam. A couple quick getuid and geteuid calls showed that my dovecot imap session was running as 'nobody', and my dovecot process is running as 'dovecot'. Adding both those to the virutal_uid tables still yielded the same error. So, i left 'dovecot' in my users table and added '--user dovecot' to the execl call.
With all of that in place, I can now move mail into or out of my SPAM folder and see dspam being called correctly and also seeing the database being updated as well.
Hopefully this helps someone out who's looking at getting this running and running into similar issues. Saw a similar thread from Stefan a few days ago, and that's what gave me enough insight to get to the bottom of this.
Ryan On Wed, April 12, 2006 7:48 am, Johannes Berg said:
On Tue, 2006-04-11 at 22:14 -0500, Ryan Kolak wrote:
found a small handful of leaks on startup, none of which look like anything directly related.. There's one more leak when the first time i load a page via squirrelmail (in the login process), but nothing after that until i kill dovecot. the full output is at the bottom if its useful at all.
There's definitely a small one-time leak when the plugin is loaded which valgrind should've shown. Are you sure that you actually used the plugin by moving some mail between normal and spam?
johannes
PGP Fingerprint - E15C CC7D 5830 AB8A C2AE 5C5E 80D8 6B63 D40B 015C
-----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.1 (GNU/Linux)
iD8DBQFEPT0UgNhrY9QLAVwRAhzLAJ96I1cdEOJ/0qR/GizTszrOO16+pwCfSztD 5ol9L7JYZ0OWDu7eOooObOM= =VyKc -----END PGP SIGNATURE-----
On Wed, 2006-04-12 at 12:47 -0500, Ryan Kolak wrote:
In trying to determine if the memory corruption was in creating the string or in storing it into our linked arrary, i first stored the result from p_strdup into a variable, inspected the results, and then had the normal line of code that called p_strdup again.
Here:
142 typedef struct dspam_signature_list * siglist_t; .. 153 n = p_malloc (pool, sizeof(siglist_t));
You're allocating sizeof(pointer) here.
That's one reason why typedefing pointers is evil. :)
On Wed, 2006-04-12 at 21:21 +0300, Timo Sirainen wrote:
142 typedef struct dspam_signature_list * siglist_t; .. 153 n = p_malloc (pool, sizeof(siglist_t));
You're allocating sizeof(pointer) here.
Amazing that it ever worked. Fixed, I hope.
johannes
Johannes Berg wrote:
On Wed, 2006-04-12 at 21:21 +0300, Timo Sirainen wrote:
142 typedef struct dspam_signature_list * siglist_t; .. 153 n = p_malloc (pool, sizeof(siglist_t));
You're allocating sizeof(pointer) here.
Amazing that it ever worked. Fixed, I hope.
johannes
Johannes, did your webserver die? Looks like the reverse proxy on sipsolutions isn't finding it :(
If it's currently down for the count, any chance of telling me where I might find the updated version of the plugin?
On Thu, 2006-04-13 at 13:12 +1000, Peter Fern wrote:
Johannes, did your webserver die? Looks like the reverse proxy on sipsolutions isn't finding it :(
Yes, in fact, the server keeps rebooting. The wiki server is local to sipsolutions, but if it just gets killed it often doesn't come back up because the PID got reassigned. Try again, and sorry about the problems.
johannes
participants (4)
-
Johannes Berg
-
Peter Fern
-
Ryan Kolak
-
Timo Sirainen