thr3ads.net - dovecot - [Dovecot] fts-solr indexer-worker connects to wrong solr host dovecot-2.2.4 [Sep 2013]

If this information is useful, please help other people find it:
Share via:

Richard Platel

2013-Sep-27 15:46 UTC

[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 at 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 at rp-auth-test.com): lookup
shared/userdb/hammer at rp-auth-test.com
auth-worker(2195): Debug: dict(hammer at 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
at rp-auth-test.com/:INDEX=/mail/index01/215/573/hammer at
rp-auth-test.com/","fts_solr":"debug
url=http://ftsvs01:8080/solr/","gid":"8"}
auth: Debug: userdb out: USER   1       hammer at 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 at
rp-auth-test.com/:INDEX=/mail/index01/215/573/hammer at rp-auth-test.com/   
fts_solr=debug url=http://ftsvs01:8080/solr/    gid=8
indexer-worker: Debug: auth input: hammer at 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 at
rp-auth-test.com/:INDEX=/mail/index01/215/573/hammer at 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 at
rp-auth-test.com/:INDEX=/mail/index01/215/573/ha
mmer at 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 at rp-auth-test.com): Debug: Effective uid=8, gid=8,
homeindexer-worker(hammer at 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 at
rp-auth-test.com/:INDEX=/mail/index01/215/573/hammer at rp-auth-test.com/
indexer-worker(hammer at rp-auth-test.com): Debug: maildir++:
root=/mail/mailstore01/215/573/hammer at rp-auth-test.com,
index=/mail/index01/215/
573/hammer at rp-auth-test.com, indexpvt=, control=,
inbox=/mail/mailstore01/215/573/hammer at rp-auth-test.com,
altindexer-worker(hammer at rp-auth-test.com): Debug: Ignoring unknown cache
field: pop3.order
indexer-worker(hammer at rp-auth-test.com): Debug: Ignoring unknown cache field:
binary.parts
indexer-worker(hammer at rp-auth-test.com): Warning: Created dotlock file's
timestamp is different than current time (1380294685 vs 1380294612
): /mail/index01/215/573/hammer at rp-auth-test.com/.INBOX/dovecot.index.log
indexer-worker(hammer at 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 at 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
at rp-auth-test.com%22]: Submitted
[...]


User2 grant at 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 at rp-auth-test.com): lookup
shared/userdb/grant at rp-auth-test.com
auth-worker(2195): Debug: dict(grant at 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
at rp-auth-test.com/:INDEX=/mail/index01/812/023/grant at
rp-auth-test.com/","fts_solr":"debug
url=http://ftsvs02:8080/solr/","gid":"8"}
auth: Debug: userdb out: USER   2       grant at 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 at
rp-auth-test.com/:INDEX=/mail/index01/812/023/grant at rp-auth-test.com/     
fts_solr=debug url=http://ftsvs02:8080/solr/    gid=8
indexer-worker(hammer at rp-auth-test.com): Debug: auth input: grant at
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 at
rp-auth-test.com/:INDEX=/mail/index01/812/023/grant at rp-auth-test.com/
fts_solr=debug url=http://ftsvs02:8080/solr/ gid=8
indexer-worker(hammer at rp-auth-test.com): Debug: Added userdb setting:
plugin/_session=cow80_609fed7600001
indexer-worker(hammer at rp-auth-test.com): Debug: Added userdb setting:
plugin/fts=solr
indexer-worker(hammer at rp-auth-test.com): Debug: Added userdb setting:
plugin/fts_solr=debug url=http://ftsvs02:8080/solr/
indexer-worker(hammer at rp-auth-test.com): Debug: Added userdb setting:
mail=maildir:/mail/mailstore01/812/023/grant at
rp-auth-test.com/:INDEX=/mail/index01/812/023/grant at rp-auth-test.com/
indexer-worker(hammer at rp-auth-test.com): Debug: Added userdb setting:
plugin/quota_rule=*:storage=5242880k
indexer-worker(hammer at rp-auth-test.com): Debug: Added userdb setting:
plugin/quota_rule2=*:messages=2684354
indexer-worker(hammer at rp-auth-test.com): Debug: Added userdb setting:
plugin/quota_rule3=Trash:ignore
indexer-worker(hammer at rp-auth-test.com): Debug: Added userdb setting:
plugin/quota_rule4=Spam:ignore
indexer-worker(grant at rp-auth-test.com): Debug: Effective uid=8, gid=8,
homeindexer-worker(grant at 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 at
rp-auth-test.com/:INDEX=/mail/index01/812/023/grant at rp-auth-test.com/
indexer-worker(grant at rp-auth-test.com): Debug: maildir++:
root=/mail/mailstore01/812/023/grant at rp-auth-test.com,
index=/mail/index01/812/023/grant at rp-auth-test.com, indexpvt=, control=,
inbox=/mail/mailstore01/812/023/grant at rp-auth-test.com,
altindexer-worker(grant at rp-auth-test.com): Debug: Ignoring unknown cache
field: pop3.order
indexer-worker(grant at rp-auth-test.com): Debug: Ignoring unknown cache field:
binary.parts
indexer-worker(grant at rp-auth-test.com): Warning: Created dotlock file's
timestamp is different than current time (1380294736 vs 1380294664):
/mail/index01/812/023/grant at rp-auth-test.com/.INBOX/dovecot.index.cache
indexer-worker(grant at rp-auth-test.com): Warning: Created dotlock file's
timestamp is different than current time (1380294736 vs 1380294664):
/mail/index01/812/023/grant at rp-auth-test.com/.INBOX/dovecot.index.log
indexer-worker(grant at rp-auth-test.com): Warning: Created dotlock file's
timestamp is different than current time (1380294736 vs 1380294664):
/mail/index01/812/023/grant at rp-auth-test.com/.INBOX/dovecot.index.cache
indexer-worker(grant at 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 at rp-auth-test.com): Debug: http-client: request [POST
http://ftsvs01:8080/solr/update]: Sent header
indexer-worker(grant at rp-auth-test.com): Debug: http-client: request [POST
http://ftsvs01:8080/solr/update]: Partially sent payload
indexer-worker(grant at rp-auth-test.com): Debug: http-client: request [POST
http://ftsvs01:8080/solr/update]: Partially sent payload
indexer-worker(grant at rp-auth-test.com): Debug: http-client: request [POST
http://ftsvs01:8080/solr/update]: Partially sent payload
indexer-worker(grant at rp-auth-test.com): Debug: http-client: request [POST
http://ftsvs01:8080/solr/update]: Partially sent payload
indexer-worker(grant at rp-auth-test.com): Debug: http-client: request [POST
http://ftsvs01:8080/solr/update]: Partially sent payload
indexer-worker(grant at 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 at 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
at rp-auth-test.com%22]: Submitted
[...]

Richard Platel

2013-Oct-02 19:28 UTC

head link

[Dovecot] fts-solr indexer-worker connects to wrong solr host dovecot-2.2.4

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 at 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 at 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 at rp-auth-test.com): lookup
shared/userdb/hammer at rp-auth-test.com
> auth-worker(2195): Debug: dict(hammer at 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
at rp-auth-test.com/:INDEX=/mail/index01/215/573/hammer at
rp-auth-test.com/","fts_solr":"debug
url=http://ftsvs01:8080/solr/","gid":"8"}
> auth: Debug: userdb out: USER   1       hammer at 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 at
rp-auth-test.com/:INDEX=/mail/index01/215/573/hammer at rp-auth-test.com/   
fts_solr=debug url=http://ftsvs01:8080/solr/    gid=8
> indexer-worker: Debug: auth input: hammer at 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 at
rp-auth-test.com/:INDEX=/mail/index01/215/573/hammer at 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 at
rp-auth-test.com/:INDEX=/mail/index01/215/573/ha
> mmer at 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 at rp-auth-test.com): Debug: Effective uid=8, gid=8,
home> indexer-worker(hammer at 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 at
rp-auth-test.com/:INDEX=/mail/index01/215/573/hammer at rp-auth-test.com/
> indexer-worker(hammer at rp-auth-test.com): Debug: maildir++:
root=/mail/mailstore01/215/573/hammer at rp-auth-test.com,
index=/mail/index01/215/
> 573/hammer at rp-auth-test.com, indexpvt=, control=,
inbox=/mail/mailstore01/215/573/hammer at rp-auth-test.com, alt>
indexer-worker(hammer at rp-auth-test.com): Debug: Ignoring unknown cache field:
pop3.order
> indexer-worker(hammer at rp-auth-test.com): Debug: Ignoring unknown cache
field: binary.parts
> indexer-worker(hammer at rp-auth-test.com): Warning: Created dotlock
file's timestamp is different than current time (1380294685 vs 1380294612
> ): /mail/index01/215/573/hammer at
rp-auth-test.com/.INBOX/dovecot.index.log
> indexer-worker(hammer at 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 at 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
at rp-auth-test.com%22]: Submitted
> [...]
> 
> 
> User2 grant at 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 at rp-auth-test.com): lookup
shared/userdb/grant at rp-auth-test.com
> auth-worker(2195): Debug: dict(grant at 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
at rp-auth-test.com/:INDEX=/mail/index01/812/023/grant at
rp-auth-test.com/","fts_solr":"debug
url=http://ftsvs02:8080/solr/","gid":"8"}
> auth: Debug: userdb out: USER   2       grant at 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 at
rp-auth-test.com/:INDEX=/mail/index01/812/023/grant at rp-auth-test.com/     
fts_solr=debug url=http://ftsvs02:8080/solr/    gid=8
> indexer-worker(hammer at rp-auth-test.com): Debug: auth input: grant at
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 at
rp-auth-test.com/:INDEX=/mail/index01/812/023/grant at rp-auth-test.com/
fts_solr=debug url=http://ftsvs02:8080/solr/ gid=8
> indexer-worker(hammer at rp-auth-test.com): Debug: Added userdb setting:
plugin/_session=cow80_609fed7600001
> indexer-worker(hammer at rp-auth-test.com): Debug: Added userdb setting:
plugin/fts=solr
> indexer-worker(hammer at rp-auth-test.com): Debug: Added userdb setting:
plugin/fts_solr=debug url=http://ftsvs02:8080/solr/
> indexer-worker(hammer at rp-auth-test.com): Debug: Added userdb setting:
mail=maildir:/mail/mailstore01/812/023/grant at
rp-auth-test.com/:INDEX=/mail/index01/812/023/grant at rp-auth-test.com/
> indexer-worker(hammer at rp-auth-test.com): Debug: Added userdb setting:
plugin/quota_rule=*:storage=5242880k
> indexer-worker(hammer at rp-auth-test.com): Debug: Added userdb setting:
plugin/quota_rule2=*:messages=2684354
> indexer-worker(hammer at rp-auth-test.com): Debug: Added userdb setting:
plugin/quota_rule3=Trash:ignore
> indexer-worker(hammer at rp-auth-test.com): Debug: Added userdb setting:
plugin/quota_rule4=Spam:ignore
> indexer-worker(grant at rp-auth-test.com): Debug: Effective uid=8, gid=8,
home> indexer-worker(grant at 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 at
rp-auth-test.com/:INDEX=/mail/index01/812/023/grant at rp-auth-test.com/
> indexer-worker(grant at rp-auth-test.com): Debug: maildir++:
root=/mail/mailstore01/812/023/grant at rp-auth-test.com,
index=/mail/index01/812/023/grant at rp-auth-test.com, indexpvt=, control=,
inbox=/mail/mailstore01/812/023/grant at rp-auth-test.com, alt>
indexer-worker(grant at rp-auth-test.com): Debug: Ignoring unknown cache field:
pop3.order
> indexer-worker(grant at rp-auth-test.com): Debug: Ignoring unknown cache
field: binary.parts
> indexer-worker(grant at rp-auth-test.com): Warning: Created dotlock
file's timestamp is different than current time (1380294736 vs 1380294664):
/mail/index01/812/023/grant at rp-auth-test.com/.INBOX/dovecot.index.cache
> indexer-worker(grant at rp-auth-test.com): Warning: Created dotlock
file's timestamp is different than current time (1380294736 vs 1380294664):
/mail/index01/812/023/grant at rp-auth-test.com/.INBOX/dovecot.index.log
> indexer-worker(grant at rp-auth-test.com): Warning: Created dotlock
file's timestamp is different than current time (1380294736 vs 1380294664):
/mail/index01/812/023/grant at rp-auth-test.com/.INBOX/dovecot.index.cache
> indexer-worker(grant at 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 at rp-auth-test.com): Debug: http-client: request
[POST http://ftsvs01:8080/solr/update]: Sent header
> indexer-worker(grant at rp-auth-test.com): Debug: http-client: request
[POST http://ftsvs01:8080/solr/update]: Partially sent payload
> indexer-worker(grant at rp-auth-test.com): Debug: http-client: request
[POST http://ftsvs01:8080/solr/update]: Partially sent payload
> indexer-worker(grant at rp-auth-test.com): Debug: http-client: request
[POST http://ftsvs01:8080/solr/update]: Partially sent payload
> indexer-worker(grant at rp-auth-test.com): Debug: http-client: request
[POST http://ftsvs01:8080/solr/update]: Partially sent payload
> indexer-worker(grant at rp-auth-test.com): Debug: http-client: request
[POST http://ftsvs01:8080/solr/update]: Partially sent payload
> indexer-worker(grant at 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 at 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
at rp-auth-test.com%22]: Submitted
> [...]
> 
> 
> 
>

Possibly Parallel Threads

Search for more reasonably related threads

dovecot - Sep 2013 - fts-solr indexer-worker connects to wrong solr host dovecot-2.2.4

[Dovecot] fts-solr indexer-worker connects to wrong solr host dovecot-2.2.4

[Dovecot] fts-solr indexer-worker connects to wrong solr host dovecot-2.2.4

Possibly Parallel Threads