[Dovecot] fts-solr indexer-worker connects to wrong solr host dovecot-2.2.4
Hello.
We're setting up fts solr and want to have the solr server host be set per-user via UserDB.
It looks like if a user connects and fts indexes mail, and then another user connects and indexes mail, indexer-worker is connecting to the first user's fts host:
User1, hammer@rp-auth-test.com connects, does a SEARCH for the first time, indexer-worker gets UserDB settings and correctly indexes mail on ftsvs01:
[...] auth-worker(2195): Debug: dict(hammer@rp-auth-test.com): lookup shared/userdb/hammer@rp-auth-test.com auth-worker(2195): Debug: dict(hammer@rp-auth-test.com): result: {"uid":"8","fts":"solr","quota_rule4":"Spam:ignore","_session":"talk15_590ec6d100042","quota_rule3":"Trash:ignore","quota_rule2":"*:messages=2684354","quota_rule":"*:storage=5242880k","mail":"maildir:/mail/mailstore01/215/573/hammer@rp-auth-test.com/:INDEX=/mail/index01/215/573/hammer@rp-auth-test.com/","fts_solr":"debug url=http://ftsvs01:8080/solr/","gid":"8"} auth: Debug: userdb out: USER 1 hammer@rp-auth-test.com uid=8 fts=solr quota_rule4=Spam:ignore _session=talk15_590ec6d100042 quota_rule3=Trash:ignore quota_rule2=*:messages=2684354 quota_rule=*:storage=5242880k mail=maildir:/mail/mailstore01/215/573/hammer@rp-auth-test.com/:INDEX=/mail/index01/215/573/hammer@rp-auth-test.com/ fts_solr=debug url=http://ftsvs01:8080/solr/ gid=8 indexer-worker: Debug: auth input: hammer@rp-auth-test.com uid=8 fts=solr quota_rule4=Spam:ignore _session=talk15_590ec6d100042 quota_rule3=Trash:ignore quota_rule2=*:messages=2684354 quota_rule=*:storage=5242880k mail=maildir:/mail/mailstore01/215/573/hammer@rp-auth-test.com/:INDEX=/mail/index01/215/573/hammer@rp-auth-test.com/ fts_solr=debug url=http://ftsvs01:8080/solr/ gid=8 indexer-worker: Debug: Added userdb setting: plugin/_session=talk15_590ec6d100042 indexer-worker: Debug: Added userdb setting: plugin/fts=solr indexer-worker: Debug: Added userdb setting: plugin/fts_solr=debug url=http://ftsvs01:8080/solr/ indexer-worker: Debug: Added userdb setting: mail=maildir:/mail/mailstore01/215/573/hammer@rp-auth-test.com/:INDEX=/mail/index01/215/573/ha mmer@rp-auth-test.com/ indexer-worker: Debug: Added userdb setting: plugin/quota_rule=*:storage=5242880k indexer-worker: Debug: Added userdb setting: plugin/quota_rule2=*:messages=2684354 indexer-worker: Debug: Added userdb setting: plugin/quota_rule3=Trash:ignore indexer-worker: Debug: Added userdb setting: plugin/quota_rule4=Spam:ignore indexer-worker(hammer@rp-auth-test.com): Debug: Effective uid=8, gid=8, home= indexer-worker(hammer@rp-auth-test.com): Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions =yes location=maildir:/mail/mailstore01/215/573/hammer@rp-auth-test.com/:INDEX=/mail/index01/215/573/hammer@rp-auth-test.com/ indexer-worker(hammer@rp-auth-test.com): Debug: maildir++: root=/mail/mailstore01/215/573/hammer@rp-auth-test.com, index=/mail/index01/215/ 573/hammer@rp-auth-test.com, indexpvt=, control=, inbox=/mail/mailstore01/215/573/hammer@rp-auth-test.com, alt= indexer-worker(hammer@rp-auth-test.com): Debug: Ignoring unknown cache field: pop3.order indexer-worker(hammer@rp-auth-test.com): Debug: Ignoring unknown cache field: binary.parts indexer-worker(hammer@rp-auth-test.com): Warning: Created dotlock file's timestamp is different than current time (1380294685 vs 1380294612 ): /mail/index01/215/573/hammer@rp-auth-test.com/.INBOX/dovecot.index.log indexer-worker(hammer@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Submitted [...]
User1 index finishes and imap searches against ftsvs01 [...] imap(hammer@rp-auth-test.com): Debug: http-client: request [GET http://ftsvs01:8080/solr/select?fl=uid,score&rows=2&sort=uid+asc&q=(hdr:%22moo%22+OR+body:%22moo%22)&fq=%2Bbox:42faee1f735b1e52b3210000386e9ade+%2Buser:%22hammer@rp-auth-test.com%22]: Submitted [...]
User2 grant@rp-auth-test.com connects and does a SEARCH, index worker gets gets UserDB settings, including fts host ftsvs02, but connects to ftsvs01 (also note index-worker initially shows wrong user in loglines) [...] auth-worker(2195): Debug: dict(grant@rp-auth-test.com): lookup shared/userdb/grant@rp-auth-test.com auth-worker(2195): Debug: dict(grant@rp-auth-test.com): result: {"uid":"8","fts":"solr","quota_rule4":"Spam:ignore","_session":"cow80_609fed7600001","quota_rule3":"Trash:ignore","quota_rule2":"*:messages=2684354","quota_rule":"*:storage=5242880k","mail":"maildir:/mail/mailstore01/812/023/grant@rp-auth-test.com/:INDEX=/mail/index01/812/023/grant@rp-auth-test.com/","fts_solr":"debug url=http://ftsvs02:8080/solr/","gid":"8"} auth: Debug: userdb out: USER 2 grant@rp-auth-test.com uid=8 fts=solr quota_rule4=Spam:ignore _session=cow80_609fed7600001 quota_rule3=Trash:ignore quota_rule2=*:messages=2684354 quota_rule=*:storage=5242880k mail=maildir:/mail/mailstore01/812/023/grant@rp-auth-test.com/:INDEX=/mail/index01/812/023/grant@rp-auth-test.com/ fts_solr=debug url=http://ftsvs02:8080/solr/ gid=8 indexer-worker(hammer@rp-auth-test.com): Debug: auth input: grant@rp-auth-test.com uid=8 fts=solr quota_rule4=Spam:ignore _session=cow80_609fed7600001 quota_rule3=Trash:ignore quota_rule2=*:messages=2684354 quota_rule=*:storage=5242880k mail=maildir:/mail/mailstore01/812/023/grant@rp-auth-test.com/:INDEX=/mail/index01/812/023/grant@rp-auth-test.com/ fts_solr=debug url=http://ftsvs02:8080/solr/ gid=8 indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/_session=cow80_609fed7600001 indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/fts=solr indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/fts_solr=debug url=http://ftsvs02:8080/solr/ indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: mail=maildir:/mail/mailstore01/812/023/grant@rp-auth-test.com/:INDEX=/mail/index01/812/023/grant@rp-auth-test.com/ indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/quota_rule=*:storage=5242880k indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/quota_rule2=*:messages=2684354 indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/quota_rule3=Trash:ignore indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/quota_rule4=Spam:ignore indexer-worker(grant@rp-auth-test.com): Debug: Effective uid=8, gid=8, home= indexer-worker(grant@rp-auth-test.com): Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/mail/mailstore01/812/023/grant@rp-auth-test.com/:INDEX=/mail/index01/812/023/grant@rp-auth-test.com/ indexer-worker(grant@rp-auth-test.com): Debug: maildir++: root=/mail/mailstore01/812/023/grant@rp-auth-test.com, index=/mail/index01/812/023/grant@rp-auth-test.com, indexpvt=, control=, inbox=/mail/mailstore01/812/023/grant@rp-auth-test.com, alt= indexer-worker(grant@rp-auth-test.com): Debug: Ignoring unknown cache field: pop3.order indexer-worker(grant@rp-auth-test.com): Debug: Ignoring unknown cache field: binary.parts indexer-worker(grant@rp-auth-test.com): Warning: Created dotlock file's timestamp is different than current time (1380294736 vs 1380294664): /mail/index01/812/023/grant@rp-auth-test.com/.INBOX/dovecot.index.cache indexer-worker(grant@rp-auth-test.com): Warning: Created dotlock file's timestamp is different than current time (1380294736 vs 1380294664): /mail/index01/812/023/grant@rp-auth-test.com/.INBOX/dovecot.index.log indexer-worker(grant@rp-auth-test.com): Warning: Created dotlock file's timestamp is different than current time (1380294736 vs 1380294664): /mail/index01/812/023/grant@rp-auth-test.com/.INBOX/dovecot.index.cache indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Submitted [...]
indexer-worker indexes User2's mail on wrong fts host: [...] indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Sent header indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Partially sent payload indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Partially sent payload indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Partially sent payload indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Partially sent payload indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Partially sent payload indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Partially sent payload [...]
indexer-worker finishes and imap searches against correct fts host ftsvs02 [...] imap(grant@rp-auth-test.com): Debug: http-client: request [GET http://ftsvs02:8080/solr/select?fl=uid,score&rows=194&sort=uid+asc&q=(hdr:%22Fasdf%22+OR+body:%22Fasdf%22)&fq=%2Bbox:62d61f003b5a1e52af130000386e9ade+%2Buser:%22grant@rp-auth-test.com%22]: Submitted [...]
I've confirmed that this problem still exists in 2.2.5
It seems that indexer-worker only init's plugins at startup, so the fts_solr plugin is holding the url= parameter from the first user.
The problem doesn't happen if the indexer-worker process is idle-killed between users. A new process starts up with the new user's userdb settings.
I thought I could work around this problem by adjusting indexer-worker's settings:
service indexer-worker { service_count = 1 idle_kill = 1 }
but these changes don't seem to have any effect, the indexer-worker process still hangs around idling after indexing a user, and isn't idle-killed for upwards of a minute.
Any help?
On 2013-09-27, at 11:46 AM, Richard Platel <rplatel@tucows.com> wrote:
Hello.
We're setting up fts solr and want to have the solr server host be set per-user via UserDB.It looks like if a user connects and fts indexes mail, and then another user connects and indexes mail, indexer-worker is connecting to the first user's fts host:
User1, hammer@rp-auth-test.com connects, does a SEARCH for the first time, indexer-worker gets UserDB settings and correctly indexes mail on ftsvs01:
[...] auth-worker(2195): Debug: dict(hammer@rp-auth-test.com): lookup shared/userdb/hammer@rp-auth-test.com auth-worker(2195): Debug: dict(hammer@rp-auth-test.com): result: {"uid":"8","fts":"solr","quota_rule4":"Spam:ignore","_session":"talk15_590ec6d100042","quota_rule3":"Trash:ignore","quota_rule2":"*:messages=2684354","quota_rule":"*:storage=5242880k","mail":"maildir:/mail/mailstore01/215/573/hammer@rp-auth-test.com/:INDEX=/mail/index01/215/573/hammer@rp-auth-test.com/","fts_solr":"debug url=http://ftsvs01:8080/solr/","gid":"8"} auth: Debug: userdb out: USER 1 hammer@rp-auth-test.com uid=8 fts=solr quota_rule4=Spam:ignore _session=talk15_590ec6d100042 quota_rule3=Trash:ignore quota_rule2=*:messages=2684354 quota_rule=*:storage=5242880k mail=maildir:/mail/mailstore01/215/573/hammer@rp-auth-test.com/:INDEX=/mail/index01/215/573/hammer@rp-auth-test.com/ fts_solr=debug url=http://ftsvs01:8080/solr/ gid=8 indexer-worker: Debug: auth input: hammer@rp-auth-test.com uid=8 fts=solr quota_rule4=Spam:ignore _session=talk15_590ec6d100042 quota_rule3=Trash:ignore quota_rule2=*:messages=2684354 quota_rule=*:storage=5242880k mail=maildir:/mail/mailstore01/215/573/hammer@rp-auth-test.com/:INDEX=/mail/index01/215/573/hammer@rp-auth-test.com/ fts_solr=debug url=http://ftsvs01:8080/solr/ gid=8 indexer-worker: Debug: Added userdb setting: plugin/_session=talk15_590ec6d100042 indexer-worker: Debug: Added userdb setting: plugin/fts=solr indexer-worker: Debug: Added userdb setting: plugin/fts_solr=debug url=http://ftsvs01:8080/solr/ indexer-worker: Debug: Added userdb setting: mail=maildir:/mail/mailstore01/215/573/hammer@rp-auth-test.com/:INDEX=/mail/index01/215/573/ha mmer@rp-auth-test.com/ indexer-worker: Debug: Added userdb setting: plugin/quota_rule=*:storage=5242880k indexer-worker: Debug: Added userdb setting: plugin/quota_rule2=*:messages=2684354 indexer-worker: Debug: Added userdb setting: plugin/quota_rule3=Trash:ignore indexer-worker: Debug: Added userdb setting: plugin/quota_rule4=Spam:ignore indexer-worker(hammer@rp-auth-test.com): Debug: Effective uid=8, gid=8, home= indexer-worker(hammer@rp-auth-test.com): Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions =yes location=maildir:/mail/mailstore01/215/573/hammer@rp-auth-test.com/:INDEX=/mail/index01/215/573/hammer@rp-auth-test.com/ indexer-worker(hammer@rp-auth-test.com): Debug: maildir++: root=/mail/mailstore01/215/573/hammer@rp-auth-test.com, index=/mail/index01/215/ 573/hammer@rp-auth-test.com, indexpvt=, control=, inbox=/mail/mailstore01/215/573/hammer@rp-auth-test.com, alt= indexer-worker(hammer@rp-auth-test.com): Debug: Ignoring unknown cache field: pop3.order indexer-worker(hammer@rp-auth-test.com): Debug: Ignoring unknown cache field: binary.parts indexer-worker(hammer@rp-auth-test.com): Warning: Created dotlock file's timestamp is different than current time (1380294685 vs 1380294612 ): /mail/index01/215/573/hammer@rp-auth-test.com/.INBOX/dovecot.index.log indexer-worker(hammer@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Submitted [...]
User1 index finishes and imap searches against ftsvs01 [...] imap(hammer@rp-auth-test.com): Debug: http-client: request [GET http://ftsvs01:8080/solr/select?fl=uid,score&rows=2&sort=uid+asc&q=(hdr:%22moo%22+OR+body:%22moo%22)&fq=%2Bbox:42faee1f735b1e52b3210000386e9ade+%2Buser:%22hammer@rp-auth-test.com%22]: Submitted [...]
User2 grant@rp-auth-test.com connects and does a SEARCH, index worker gets gets UserDB settings, including fts host ftsvs02, but connects to ftsvs01 (also note index-worker initially shows wrong user in loglines) [...] auth-worker(2195): Debug: dict(grant@rp-auth-test.com): lookup shared/userdb/grant@rp-auth-test.com auth-worker(2195): Debug: dict(grant@rp-auth-test.com): result: {"uid":"8","fts":"solr","quota_rule4":"Spam:ignore","_session":"cow80_609fed7600001","quota_rule3":"Trash:ignore","quota_rule2":"*:messages=2684354","quota_rule":"*:storage=5242880k","mail":"maildir:/mail/mailstore01/812/023/grant@rp-auth-test.com/:INDEX=/mail/index01/812/023/grant@rp-auth-test.com/","fts_solr":"debug url=http://ftsvs02:8080/solr/","gid":"8"} auth: Debug: userdb out: USER 2 grant@rp-auth-test.com uid=8 fts=solr quota_rule4=Spam:ignore _session=cow80_609fed7600001 quota_rule3=Trash:ignore quota_rule2=*:messages=2684354 quota_rule=*:storage=5242880k mail=maildir:/mail/mailstore01/812/023/grant@rp-auth-test.com/:INDEX=/mail/index01/812/023/grant@rp-auth-test.com/ fts_solr=debug url=http://ftsvs02:8080/solr/ gid=8 indexer-worker(hammer@rp-auth-test.com): Debug: auth input: grant@rp-auth-test.com uid=8 fts=solr quota_rule4=Spam:ignore _session=cow80_609fed7600001 quota_rule3=Trash:ignore quota_rule2=*:messages=2684354 quota_rule=*:storage=5242880k mail=maildir:/mail/mailstore01/812/023/grant@rp-auth-test.com/:INDEX=/mail/index01/812/023/grant@rp-auth-test.com/ fts_solr=debug url=http://ftsvs02:8080/solr/ gid=8 indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/_session=cow80_609fed7600001 indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/fts=solr indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/fts_solr=debug url=http://ftsvs02:8080/solr/ indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: mail=maildir:/mail/mailstore01/812/023/grant@rp-auth-test.com/:INDEX=/mail/index01/812/023/grant@rp-auth-test.com/ indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/quota_rule=*:storage=5242880k indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/quota_rule2=*:messages=2684354 indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/quota_rule3=Trash:ignore indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/quota_rule4=Spam:ignore indexer-worker(grant@rp-auth-test.com): Debug: Effective uid=8, gid=8, home= indexer-worker(grant@rp-auth-test.com): Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/mail/mailstore01/812/023/grant@rp-auth-test.com/:INDEX=/mail/index01/812/023/grant@rp-auth-test.com/ indexer-worker(grant@rp-auth-test.com): Debug: maildir++: root=/mail/mailstore01/812/023/grant@rp-auth-test.com, index=/mail/index01/812/023/grant@rp-auth-test.com, indexpvt=, control=, inbox=/mail/mailstore01/812/023/grant@rp-auth-test.com, alt= indexer-worker(grant@rp-auth-test.com): Debug: Ignoring unknown cache field: pop3.order indexer-worker(grant@rp-auth-test.com): Debug: Ignoring unknown cache field: binary.parts indexer-worker(grant@rp-auth-test.com): Warning: Created dotlock file's timestamp is different than current time (1380294736 vs 1380294664): /mail/index01/812/023/grant@rp-auth-test.com/.INBOX/dovecot.index.cache indexer-worker(grant@rp-auth-test.com): Warning: Created dotlock file's timestamp is different than current time (1380294736 vs 1380294664): /mail/index01/812/023/grant@rp-auth-test.com/.INBOX/dovecot.index.log indexer-worker(grant@rp-auth-test.com): Warning: Created dotlock file's timestamp is different than current time (1380294736 vs 1380294664): /mail/index01/812/023/grant@rp-auth-test.com/.INBOX/dovecot.index.cache indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Submitted [...]
indexer-worker indexes User2's mail on wrong fts host: [...] indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Sent header indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Partially sent payload indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Partially sent payload indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Partially sent payload indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Partially sent payload indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Partially sent payload indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Partially sent payload [...]
indexer-worker finishes and imap searches against correct fts host ftsvs02 [...] imap(grant@rp-auth-test.com): Debug: http-client: request [GET http://ftsvs02:8080/solr/select?fl=uid,score&rows=194&sort=uid+asc&q=(hdr:%22Fasdf%22+OR+body:%22Fasdf%22)&fq=%2Bbox:62d61f003b5a1e52af130000386e9ade+%2Buser:%22grant@rp-auth-test.com%22]: Submitted [...]
Did some more digging. The problem is that the fts-solr plugin has a global solr_conn pointer, that persists between users. I think this patch fixes the problem: --- a/dovecot/fts_solr_plugin/fts-solr-plugin.c +++ b/dovecot/fts_solr_plugin/fts-solr-plugin.c @@ -50,6 +50,13 @@ static void fts_solr_mail_user_create(struct mail_user *user, const char *env) { struct fts_solr_user *fuser; + /** solr URL may be different per-user **/ + if (solr_conn != NULL) { + solr_connection_deinit(solr_conn); + solr_conn = NULL; + } + /**/ + fuser = p_new(user->pool, struct fts_solr_user, 1); if (fts_solr_plugin_init_settings(user, &fuser->set, env) < 0) { /* invalid settings, disabling */ On 2013-10-02, at 3:28 PM, Richard Platel <rplatel@tucows.com> wrote:
I've confirmed that this problem still exists in 2.2.5
It seems that indexer-worker only init's plugins at startup, so the fts_solr plugin is holding the url= parameter from the first user.
The problem doesn't happen if the indexer-worker process is idle-killed between users. A new process starts up with the new user's userdb settings.
I thought I could work around this problem by adjusting indexer-worker's settings:
service indexer-worker { service_count = 1 idle_kill = 1 }
but these changes don't seem to have any effect, the indexer-worker process still hangs around idling after indexing a user, and isn't idle-killed for upwards of a minute.
Any help?
On 2013-09-27, at 11:46 AM, Richard Platel <rplatel@tucows.com> wrote:
Hello. We're setting up fts solr and want to have the solr server host be set per-user via UserDB.
It looks like if a user connects and fts indexes mail, and then another user connects and indexes mail, indexer-worker is connecting to the first user's fts host:
User1, hammer@rp-auth-test.com connects, does a SEARCH for the first time, indexer-worker gets UserDB settings and correctly indexes mail on ftsvs01:
[...] auth-worker(2195): Debug: dict(hammer@rp-auth-test.com): lookup shared/userdb/hammer@rp-auth-test.com auth-worker(2195): Debug: dict(hammer@rp-auth-test.com): result: {"uid":"8","fts":"solr","quota_rule4":"Spam:ignore","_session":"talk15_590ec6d100042","quota_rule3":"Trash:ignore","quota_rule2":"*:messages=2684354","quota_rule":"*:storage=5242880k","mail":"maildir:/mail/mailstore01/215/573/hammer@rp-auth-test.com/:INDEX=/mail/index01/215/573/hammer@rp-auth-test.com/","fts_solr":"debug url=http://ftsvs01:8080/solr/","gid":"8"} auth: Debug: userdb out: USER 1 hammer@rp-auth-test.com uid=8 fts=solr quota_rule4=Spam:ignore _session=talk15_590ec6d100042 quota_rule3=Trash:ignore quota_rule2=*:messages=2684354 quota_rule=*:storage=5242880k mail=maildir:/mail/mailstore01/215/573/hammer@rp-auth-test.com/:INDEX=/mail/index01/215/573/hammer@rp-auth-test.com/ fts_solr=debug url=http://ftsvs01:8080/solr/ gid=8 indexer-worker: Debug: auth input: hammer@rp-auth-test.com uid=8 fts=solr quota_rule4=Spam:ignore _session=talk15_590ec6d100042 quota_rule3=Trash:ignore quota_rule2=*:messages=2684354 quota_rule=*:storage=5242880k mail=maildir:/mail/mailstore01/215/573/hammer@rp-auth-test.com/:INDEX=/mail/index01/215/573/hammer@rp-auth-test.com/ fts_solr=debug url=http://ftsvs01:8080/solr/ gid=8 indexer-worker: Debug: Added userdb setting: plugin/_session=talk15_590ec6d100042 indexer-worker: Debug: Added userdb setting: plugin/fts=solr indexer-worker: Debug: Added userdb setting: plugin/fts_solr=debug url=http://ftsvs01:8080/solr/ indexer-worker: Debug: Added userdb setting: mail=maildir:/mail/mailstore01/215/573/hammer@rp-auth-test.com/:INDEX=/mail/index01/215/573/ha mmer@rp-auth-test.com/ indexer-worker: Debug: Added userdb setting: plugin/quota_rule=*:storage=5242880k indexer-worker: Debug: Added userdb setting: plugin/quota_rule2=*:messages=2684354 indexer-worker: Debug: Added userdb setting: plugin/quota_rule3=Trash:ignore indexer-worker: Debug: Added userdb setting: plugin/quota_rule4=Spam:ignore indexer-worker(hammer@rp-auth-test.com): Debug: Effective uid=8, gid=8, home= indexer-worker(hammer@rp-auth-test.com): Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions =yes location=maildir:/mail/mailstore01/215/573/hammer@rp-auth-test.com/:INDEX=/mail/index01/215/573/hammer@rp-auth-test.com/ indexer-worker(hammer@rp-auth-test.com): Debug: maildir++: root=/mail/mailstore01/215/573/hammer@rp-auth-test.com, index=/mail/index01/215/ 573/hammer@rp-auth-test.com, indexpvt=, control=, inbox=/mail/mailstore01/215/573/hammer@rp-auth-test.com, alt= indexer-worker(hammer@rp-auth-test.com): Debug: Ignoring unknown cache field: pop3.order indexer-worker(hammer@rp-auth-test.com): Debug: Ignoring unknown cache field: binary.parts indexer-worker(hammer@rp-auth-test.com): Warning: Created dotlock file's timestamp is different than current time (1380294685 vs 1380294612 ): /mail/index01/215/573/hammer@rp-auth-test.com/.INBOX/dovecot.index.log indexer-worker(hammer@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Submitted [...]
User1 index finishes and imap searches against ftsvs01 [...] imap(hammer@rp-auth-test.com): Debug: http-client: request [GET http://ftsvs01:8080/solr/select?fl=uid,score&rows=2&sort=uid+asc&q=(hdr:%22moo%22+OR+body:%22moo%22)&fq=%2Bbox:42faee1f735b1e52b3210000386e9ade+%2Buser:%22hammer@rp-auth-test.com%22]: Submitted [...]
User2 grant@rp-auth-test.com connects and does a SEARCH, index worker gets gets UserDB settings, including fts host ftsvs02, but connects to ftsvs01 (also note index-worker initially shows wrong user in loglines) [...] auth-worker(2195): Debug: dict(grant@rp-auth-test.com): lookup shared/userdb/grant@rp-auth-test.com auth-worker(2195): Debug: dict(grant@rp-auth-test.com): result: {"uid":"8","fts":"solr","quota_rule4":"Spam:ignore","_session":"cow80_609fed7600001","quota_rule3":"Trash:ignore","quota_rule2":"*:messages=2684354","quota_rule":"*:storage=5242880k","mail":"maildir:/mail/mailstore01/812/023/grant@rp-auth-test.com/:INDEX=/mail/index01/812/023/grant@rp-auth-test.com/","fts_solr":"debug url=http://ftsvs02:8080/solr/","gid":"8"} auth: Debug: userdb out: USER 2 grant@rp-auth-test.com uid=8 fts=solr quota_rule4=Spam:ignore _session=cow80_609fed7600001 quota_rule3=Trash:ignore quota_rule2=*:messages=2684354 quota_rule=*:storage=5242880k mail=maildir:/mail/mailstore01/812/023/grant@rp-auth-test.com/:INDEX=/mail/index01/812/023/grant@rp-auth-test.com/ fts_solr=debug url=http://ftsvs02:8080/solr/ gid=8 indexer-worker(hammer@rp-auth-test.com): Debug: auth input: grant@rp-auth-test.com uid=8 fts=solr quota_rule4=Spam:ignore _session=cow80_609fed7600001 quota_rule3=Trash:ignore quota_rule2=*:messages=2684354 quota_rule=*:storage=5242880k mail=maildir:/mail/mailstore01/812/023/grant@rp-auth-test.com/:INDEX=/mail/index01/812/023/grant@rp-auth-test.com/ fts_solr=debug url=http://ftsvs02:8080/solr/ gid=8 indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/_session=cow80_609fed7600001 indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/fts=solr indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/fts_solr=debug url=http://ftsvs02:8080/solr/ indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: mail=maildir:/mail/mailstore01/812/023/grant@rp-auth-test.com/:INDEX=/mail/index01/812/023/grant@rp-auth-test.com/ indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/quota_rule=*:storage=5242880k indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/quota_rule2=*:messages=2684354 indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/quota_rule3=Trash:ignore indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/quota_rule4=Spam:ignore indexer-worker(grant@rp-auth-test.com): Debug: Effective uid=8, gid=8, home= indexer-worker(grant@rp-auth-test.com): Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/mail/mailstore01/812/023/grant@rp-auth-test.com/:INDEX=/mail/index01/812/023/grant@rp-auth-test.com/ indexer-worker(grant@rp-auth-test.com): Debug: maildir++: root=/mail/mailstore01/812/023/grant@rp-auth-test.com, index=/mail/index01/812/023/grant@rp-auth-test.com, indexpvt=, control=, inbox=/mail/mailstore01/812/023/grant@rp-auth-test.com, alt= indexer-worker(grant@rp-auth-test.com): Debug: Ignoring unknown cache field: pop3.order indexer-worker(grant@rp-auth-test.com): Debug: Ignoring unknown cache field: binary.parts indexer-worker(grant@rp-auth-test.com): Warning: Created dotlock file's timestamp is different than current time (1380294736 vs 1380294664): /mail/index01/812/023/grant@rp-auth-test.com/.INBOX/dovecot.index.cache indexer-worker(grant@rp-auth-test.com): Warning: Created dotlock file's timestamp is different than current time (1380294736 vs 1380294664): /mail/index01/812/023/grant@rp-auth-test.com/.INBOX/dovecot.index.log indexer-worker(grant@rp-auth-test.com): Warning: Created dotlock file's timestamp is different than current time (1380294736 vs 1380294664): /mail/index01/812/023/grant@rp-auth-test.com/.INBOX/dovecot.index.cache indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Submitted [...]
indexer-worker indexes User2's mail on wrong fts host: [...] indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Sent header indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Partially sent payload indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Partially sent payload indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Partially sent payload indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Partially sent payload indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Partially sent payload indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Partially sent payload [...]
indexer-worker finishes and imap searches against correct fts host ftsvs02 [...] imap(grant@rp-auth-test.com): Debug: http-client: request [GET http://ftsvs02:8080/solr/select?fl=uid,score&rows=194&sort=uid+asc&q=(hdr:%22Fasdf%22+OR+body:%22Fasdf%22)&fq=%2Bbox:62d61f003b5a1e52af130000386e9ade+%2Buser:%22grant@rp-auth-test.com%22]: Submitted [...]
Here’s a more complex fix that reuses the HTTP connections for the same hosts: http://hg.dovecot.org/dovecot-2.2/rev/26355654c314 On 3.10.2013, at 19.27, Richard Platel <rplatel@tucows.com> wrote:
Did some more digging.
The problem is that the fts-solr plugin has a global solr_conn pointer, that persists between users. I think this patch fixes the problem:
--- a/dovecot/fts_solr_plugin/fts-solr-plugin.c +++ b/dovecot/fts_solr_plugin/fts-solr-plugin.c @@ -50,6 +50,13 @@ static void fts_solr_mail_user_create(struct mail_user *user, const char *env) { struct fts_solr_user *fuser;
+ /** solr URL may be different per-user **/ + if (solr_conn != NULL) { + solr_connection_deinit(solr_conn); + solr_conn = NULL; + } + /**/ + fuser = p_new(user->pool, struct fts_solr_user, 1); if (fts_solr_plugin_init_settings(user, &fuser->set, env) < 0) { /* invalid settings, disabling */
On 2013-10-02, at 3:28 PM, Richard Platel <rplatel@tucows.com> wrote:
I've confirmed that this problem still exists in 2.2.5
It seems that indexer-worker only init's plugins at startup, so the fts_solr plugin is holding the url= parameter from the first user.
The problem doesn't happen if the indexer-worker process is idle-killed between users. A new process starts up with the new user's userdb settings.
I thought I could work around this problem by adjusting indexer-worker's settings:
service indexer-worker { service_count = 1 idle_kill = 1 }
but these changes don't seem to have any effect, the indexer-worker process still hangs around idling after indexing a user, and isn't idle-killed for upwards of a minute.
Any help?
On 2013-09-27, at 11:46 AM, Richard Platel <rplatel@tucows.com> wrote:
Hello. We're setting up fts solr and want to have the solr server host be set per-user via UserDB.
It looks like if a user connects and fts indexes mail, and then another user connects and indexes mail, indexer-worker is connecting to the first user's fts host:
User1, hammer@rp-auth-test.com connects, does a SEARCH for the first time, indexer-worker gets UserDB settings and correctly indexes mail on ftsvs01:
[...] auth-worker(2195): Debug: dict(hammer@rp-auth-test.com): lookup shared/userdb/hammer@rp-auth-test.com auth-worker(2195): Debug: dict(hammer@rp-auth-test.com): result: {"uid":"8","fts":"solr","quota_rule4":"Spam:ignore","_session":"talk15_590ec6d100042","quota_rule3":"Trash:ignore","quota_rule2":"*:messages=2684354","quota_rule":"*:storage=5242880k","mail":"maildir:/mail/mailstore01/215/573/hammer@rp-auth-test.com/:INDEX=/mail/index01/215/573/hammer@rp-auth-test.com/","fts_solr":"debug url=http://ftsvs01:8080/solr/","gid":"8"} auth: Debug: userdb out: USER 1 hammer@rp-auth-test.com uid=8 fts=solr quota_rule4=Spam:ignore _session=talk15_590ec6d100042 quota_rule3=Trash:ignore quota_rule2=*:messages=2684354 quota_rule=*:storage=5242880k mail=maildir:/mail/mailstore01/215/573/hammer@rp-auth-test.com/:INDEX=/mail/index01/215/573/hammer@rp-auth-test.com/ fts_solr=debug url=http://ftsvs01:8080/solr/ gid=8 indexer-worker: Debug: auth input: hammer@rp-auth-test.com uid=8 fts=solr quota_rule4=Spam:ignore _session=talk15_590ec6d100042 quota_rule3=Trash:ignore quota_rule2=*:messages=2684354 quota_rule=*:storage=5242880k mail=maildir:/mail/mailstore01/215/573/hammer@rp-auth-test.com/:INDEX=/mail/index01/215/573/hammer@rp-auth-test.com/ fts_solr=debug url=http://ftsvs01:8080/solr/ gid=8 indexer-worker: Debug: Added userdb setting: plugin/_session=talk15_590ec6d100042 indexer-worker: Debug: Added userdb setting: plugin/fts=solr indexer-worker: Debug: Added userdb setting: plugin/fts_solr=debug url=http://ftsvs01:8080/solr/ indexer-worker: Debug: Added userdb setting: mail=maildir:/mail/mailstore01/215/573/hammer@rp-auth-test.com/:INDEX=/mail/index01/215/573/ha mmer@rp-auth-test.com/ indexer-worker: Debug: Added userdb setting: plugin/quota_rule=*:storage=5242880k indexer-worker: Debug: Added userdb setting: plugin/quota_rule2=*:messages=2684354 indexer-worker: Debug: Added userdb setting: plugin/quota_rule3=Trash:ignore indexer-worker: Debug: Added userdb setting: plugin/quota_rule4=Spam:ignore indexer-worker(hammer@rp-auth-test.com): Debug: Effective uid=8, gid=8, home= indexer-worker(hammer@rp-auth-test.com): Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions =yes location=maildir:/mail/mailstore01/215/573/hammer@rp-auth-test.com/:INDEX=/mail/index01/215/573/hammer@rp-auth-test.com/ indexer-worker(hammer@rp-auth-test.com): Debug: maildir++: root=/mail/mailstore01/215/573/hammer@rp-auth-test.com, index=/mail/index01/215/ 573/hammer@rp-auth-test.com, indexpvt=, control=, inbox=/mail/mailstore01/215/573/hammer@rp-auth-test.com, alt= indexer-worker(hammer@rp-auth-test.com): Debug: Ignoring unknown cache field: pop3.order indexer-worker(hammer@rp-auth-test.com): Debug: Ignoring unknown cache field: binary.parts indexer-worker(hammer@rp-auth-test.com): Warning: Created dotlock file's timestamp is different than current time (1380294685 vs 1380294612 ): /mail/index01/215/573/hammer@rp-auth-test.com/.INBOX/dovecot.index.log indexer-worker(hammer@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Submitted [...]
User1 index finishes and imap searches against ftsvs01 [...] imap(hammer@rp-auth-test.com): Debug: http-client: request [GET http://ftsvs01:8080/solr/select?fl=uid,score&rows=2&sort=uid+asc&q=(hdr:%22moo%22+OR+body:%22moo%22)&fq=%2Bbox:42faee1f735b1e52b3210000386e9ade+%2Buser:%22hammer@rp-auth-test.com%22]: Submitted [...]
User2 grant@rp-auth-test.com connects and does a SEARCH, index worker gets gets UserDB settings, including fts host ftsvs02, but connects to ftsvs01 (also note index-worker initially shows wrong user in loglines) [...] auth-worker(2195): Debug: dict(grant@rp-auth-test.com): lookup shared/userdb/grant@rp-auth-test.com auth-worker(2195): Debug: dict(grant@rp-auth-test.com): result: {"uid":"8","fts":"solr","quota_rule4":"Spam:ignore","_session":"cow80_609fed7600001","quota_rule3":"Trash:ignore","quota_rule2":"*:messages=2684354","quota_rule":"*:storage=5242880k","mail":"maildir:/mail/mailstore01/812/023/grant@rp-auth-test.com/:INDEX=/mail/index01/812/023/grant@rp-auth-test.com/","fts_solr":"debug url=http://ftsvs02:8080/solr/","gid":"8"} auth: Debug: userdb out: USER 2 grant@rp-auth-test.com uid=8 fts=solr quota_rule4=Spam:ignore _session=cow80_609fed7600001 quota_rule3=Trash:ignore quota_rule2=*:messages=2684354 quota_rule=*:storage=5242880k mail=maildir:/mail/mailstore01/812/023/grant@rp-auth-test.com/:INDEX=/mail/index01/812/023/grant@rp-auth-test.com/ fts_solr=debug url=http://ftsvs02:8080/solr/ gid=8 indexer-worker(hammer@rp-auth-test.com): Debug: auth input: grant@rp-auth-test.com uid=8 fts=solr quota_rule4=Spam:ignore _session=cow80_609fed7600001 quota_rule3=Trash:ignore quota_rule2=*:messages=2684354 quota_rule=*:storage=5242880k mail=maildir:/mail/mailstore01/812/023/grant@rp-auth-test.com/:INDEX=/mail/index01/812/023/grant@rp-auth-test.com/ fts_solr=debug url=http://ftsvs02:8080/solr/ gid=8 indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/_session=cow80_609fed7600001 indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/fts=solr indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/fts_solr=debug url=http://ftsvs02:8080/solr/ indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: mail=maildir:/mail/mailstore01/812/023/grant@rp-auth-test.com/:INDEX=/mail/index01/812/023/grant@rp-auth-test.com/ indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/quota_rule=*:storage=5242880k indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/quota_rule2=*:messages=2684354 indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/quota_rule3=Trash:ignore indexer-worker(hammer@rp-auth-test.com): Debug: Added userdb setting: plugin/quota_rule4=Spam:ignore indexer-worker(grant@rp-auth-test.com): Debug: Effective uid=8, gid=8, home= indexer-worker(grant@rp-auth-test.com): Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/mail/mailstore01/812/023/grant@rp-auth-test.com/:INDEX=/mail/index01/812/023/grant@rp-auth-test.com/ indexer-worker(grant@rp-auth-test.com): Debug: maildir++: root=/mail/mailstore01/812/023/grant@rp-auth-test.com, index=/mail/index01/812/023/grant@rp-auth-test.com, indexpvt=, control=, inbox=/mail/mailstore01/812/023/grant@rp-auth-test.com, alt= indexer-worker(grant@rp-auth-test.com): Debug: Ignoring unknown cache field: pop3.order indexer-worker(grant@rp-auth-test.com): Debug: Ignoring unknown cache field: binary.parts indexer-worker(grant@rp-auth-test.com): Warning: Created dotlock file's timestamp is different than current time (1380294736 vs 1380294664): /mail/index01/812/023/grant@rp-auth-test.com/.INBOX/dovecot.index.cache indexer-worker(grant@rp-auth-test.com): Warning: Created dotlock file's timestamp is different than current time (1380294736 vs 1380294664): /mail/index01/812/023/grant@rp-auth-test.com/.INBOX/dovecot.index.log indexer-worker(grant@rp-auth-test.com): Warning: Created dotlock file's timestamp is different than current time (1380294736 vs 1380294664): /mail/index01/812/023/grant@rp-auth-test.com/.INBOX/dovecot.index.cache indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Submitted [...]
indexer-worker indexes User2's mail on wrong fts host: [...] indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Sent header indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Partially sent payload indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Partially sent payload indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Partially sent payload indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Partially sent payload indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Partially sent payload indexer-worker(grant@rp-auth-test.com): Debug: http-client: request [POST http://ftsvs01:8080/solr/update]: Partially sent payload [...]
indexer-worker finishes and imap searches against correct fts host ftsvs02 [...] imap(grant@rp-auth-test.com): Debug: http-client: request [GET http://ftsvs02:8080/solr/select?fl=uid,score&rows=194&sort=uid+asc&q=(hdr:%22Fasdf%22+OR+body:%22Fasdf%22)&fq=%2Bbox:62d61f003b5a1e52af130000386e9ade+%2Buser:%22grant@rp-auth-test.com%22]: Submitted [...]
participants (2)
-
Richard Platel
-
Timo Sirainen