Aki Tuomi
2016-Oct-17 05:51 UTC
Dict proxy client returning empty string instead of multiline string
Hi! This does sound like a bug, we'll have look. Aki On 17.10.2016 01:26, Pierre Jaury wrote:> I dived a little bit further into the rabbit hole, up to the point where > debugging has become unpracticle but I still haven't found the root > cause for sure. > > I read most of the code for "p_strdup" based on datastack memory pools > (which are used for dictionary lookups both with doveadm and by extdata) > and it seems ok. Still, after "t_malloc_real" is called in "t_malloc0", > the allocated buffer has the same address as the source string. > > The only sensible explanation I can come up with is that during > unescaping, strings are not allocated properly, leading to the memory > pool reusing the string address and zeroing it in the process before the > string copy operation. > > I will follow on this path tomorrow, any lead is more than welcome. > > kaiyou. > > On 10/16/2016 11:16 PM, Pierre Jaury wrote: >> Hello, >> >> I am using a dict proxy for my sieve extdata plugin to access some >> fields from an SQLite database (autoreply text and other >> database-configured items). >> >> All tests are performed against version 2.2.25. >> >> $ dovecot --version >> 2.2.25 (7be1766) >> >> My configuration looks like: >> >> dict { >> sieve = sqlite:/etc/dovecot/pigeonhole-sieve.dict >> } >> >> [...] >> sieve_extdata_dict_uri = proxy::sieve >> >> I am able to read pretty much any attribute without any issue, except >> when the value contains a special character like "\r" or "\n". By using >> the doveadm dict client, I narrowed it down to the dictionary management >> part (either server, protocol or client). >> >> I was suspecting escaping functions from "lib/strescape.c" (mostly >> str_tabescape and its counterpart, used by "lib-dict/client.c"), so I >> monitored socket communications. It seems that escaping is done properly >> on the server and the socket is not an issue either. >> >> The following strace dump results from running "doveadm dict get" >> against the dict socket: >> >> connect(8, {sa_family=AF_UNIX, sun_path="..."}, 110) = 0 >> fstat(8, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0 >> [...] >> write(8, "H2\t0\t0\tadmin at domain.tld\tsieve\n", 30) = 30 >> [...] >> read(8, "Otest\1r\1ntest\n", 8192) = 14 >> >> Indeed "\1r" and "\1n" are the escape sequences used by >> "lib/strescape.c". I went deeped and debugged the call to "dict_lookup" >> performed by doveadm. Indeed the client gets the proper string from the >> socket and to my surprise, it is properly unescaped. >> >> Then, in "client_dict_lookup" ("lib-dict/dict-client.c"), the call to >> "p_strdup" returns an empty string (null byte set at the target address). >> >> Before the call to the dict "->lookup" attribute (client_dict_lookup): >> >> RAX: 0x7ffff73a37c0 (push r14) >> RBX: 0x6831b8 ("priv/reply_body") >> RCX: 0x7fffffffe240 --> 0x682a60 --> 0x6831b8 ("priv/reply_body") >> RDX: 0x6831b8 ("priv/reply_body") >> RSI: 0x683288 --> 0x7ffff7653120 --> 0x7ffff73ea620 ([...]) >> RDI: 0x690ad0 --> 0x7ffff7400713 --> 0x75250079786f7270 ('proxy') >> >> 0x7ffff73a1f10 <dict_lookup+32>: mov rcx,r11 (value_r) >> 0x7ffff73a1f13 <dict_lookup+35>: mov rdx,r8 (key) >> 0x7ffff73a1f16 <dict_lookup+38>: mov rsi,r10 (pool) >> 0x7ffff73a1f19 <dict_lookup+41>: mov rdi,r9 (dict) >> 0x7ffff73a1f1c <dict_lookup+44>: add rsp,0x8 >> => 0x7ffff73a1f20 <dict_lookup+48>: jmp rax >> >> Before the call to p_strdup in "client_dict_lookup": >> >> RSI: 0x6832d8 ("test\r\ntest") (lookup.result.value) >> RDI: 0x683288 --> 0x7ffff7653120 --> [...] (pool) >> RAX: 0x0 (result) >> >> 0x7ffff73a384f: nop >> 0x7ffff73a3850: mov rsi,QWORD PTR [rsp+0x8] >> 0x7ffff73a3855: mov rdi,r14 >> => 0x7ffff73a3858: call 0x7ffff736d3c0 <p_strdup at plt> >> 0x7ffff73a385d: mov QWORD PTR [r13+0x0],rax >> 0x7ffff73a3861: mov rsi,QWORD PTR [rsp+0x18] >> 0x7ffff73a3866: xor rsi,QWORD PTR fs:0x28 >> 0x7ffff73a386f: mov eax,ebx >> >> After the call: >> >> 0x7ffff73a3850: mov rsi,QWORD PTR [rsp+0x8] >> 0x7ffff73a3855: mov rdi,r14 >> 0x7ffff73a3858: call 0x7ffff736d3c0 <p_strdup at plt> >> => 0x7ffff73a385d: mov QWORD PTR [r13+0x0],rax >> 0x7ffff73a3861: mov rsi,QWORD PTR [rsp+0x18] >> 0x7ffff73a3866: xor rsi,QWORD PTR fs:0x28 >> 0x7ffff73a386f: mov eax,ebx >> 0x7ffff73a3871: jne 0x7ffff73a38da >> >> RSI: 0x0 >> RDI: 0x6832d8 --> 0x0 >> RAX: 0x6832d8 --> 0x0 (result) >> >> It is worth noting that I can reproduce the exact same execution flow >> with a non-multiline result string (lookup.result.value) that is >> properly copied by "p_strdup" and returned in RAX, then displayed by >> doveadm. >> >> I am not familiar with the pooling mechanism hidden behind the call to >> p_strdump and not quite sure why this behaviour is emerging. Maybe I am >> even miles away from an understanding of the issue here, but it sounds >> to me like something is wrong in the way "p_strdup" performs the copy. >> >> Hope this helps, >> kaiyou. >> >> >>
Pierre Jaury
2016-Oct-17 07:52 UTC
Dict proxy client returning empty string instead of multiline string
While trying to isolate properly and reproduce, I was able to trigger the same bug with the following code: struct dict *dict; char* dict_uri = "proxy::sieve"; char* key = "priv/key"; char* username = "admin at domain.tld"; char* value, error; dict_drivers_register_builtin(); dict_init(dict_uri, DICT_DATA_TYPE_STRING, username, doveadm_settings->base_dir, &dict, &error); dict_lookup(dict, pool_datastack_create(), key, &value); printf(">%s\n", value); // outputs an empty string dict_deinit(&dict); I trimmed it to the bare minimal string manipulation functions involved but cannot reproduce in that case: pool_t pool = pool_datastack_create(); char* s1 = "test\001n\001rtest"; char* s2 = t_str_tabunescape(s1); char* s3 = p_strdup(pool, s2); printf("1>%s\n", s1); printf("2>%s\n", s2); printf("3>%s\n", s3); // all three output the string with NL and CR Maybe I am missing a function call in the process or maybe the issue is related to the way unescaping is performed in the async callback function in "dict-client.c", or maybe even some other edge case. Finally, I was able to run the first snippet without bug by removing the string duplication in "t_str_tabunescape" (which I realize is not a proper solution), or by explicitely using the following pool: return str_tabunescape(p_strdup(pool_datastack_create(), str)); Hope this helps. kaiyou On 10/17/2016 07:51 AM, Aki Tuomi wrote:> Hi! > > This does sound like a bug, we'll have look. > > Aki > > > On 17.10.2016 01:26, Pierre Jaury wrote: >> I dived a little bit further into the rabbit hole, up to the point where >> debugging has become unpracticle but I still haven't found the root >> cause for sure. >> >> I read most of the code for "p_strdup" based on datastack memory pools >> (which are used for dictionary lookups both with doveadm and by extdata) >> and it seems ok. Still, after "t_malloc_real" is called in "t_malloc0", >> the allocated buffer has the same address as the source string. >> >> The only sensible explanation I can come up with is that during >> unescaping, strings are not allocated properly, leading to the memory >> pool reusing the string address and zeroing it in the process before the >> string copy operation. >> >> I will follow on this path tomorrow, any lead is more than welcome. >> >> kaiyou. >> >> On 10/16/2016 11:16 PM, Pierre Jaury wrote: >>> Hello, >>> >>> I am using a dict proxy for my sieve extdata plugin to access some >>> fields from an SQLite database (autoreply text and other >>> database-configured items). >>> >>> All tests are performed against version 2.2.25. >>> >>> $ dovecot --version >>> 2.2.25 (7be1766) >>> >>> My configuration looks like: >>> >>> dict { >>> sieve = sqlite:/etc/dovecot/pigeonhole-sieve.dict >>> } >>> >>> [...] >>> sieve_extdata_dict_uri = proxy::sieve >>> >>> I am able to read pretty much any attribute without any issue, except >>> when the value contains a special character like "\r" or "\n". By using >>> the doveadm dict client, I narrowed it down to the dictionary management >>> part (either server, protocol or client). >>> >>> I was suspecting escaping functions from "lib/strescape.c" (mostly >>> str_tabescape and its counterpart, used by "lib-dict/client.c"), so I >>> monitored socket communications. It seems that escaping is done properly >>> on the server and the socket is not an issue either. >>> >>> The following strace dump results from running "doveadm dict get" >>> against the dict socket: >>> >>> connect(8, {sa_family=AF_UNIX, sun_path="..."}, 110) = 0 >>> fstat(8, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0 >>> [...] >>> write(8, "H2\t0\t0\tadmin at domain.tld\tsieve\n", 30) = 30 >>> [...] >>> read(8, "Otest\1r\1ntest\n", 8192) = 14 >>> >>> Indeed "\1r" and "\1n" are the escape sequences used by >>> "lib/strescape.c". I went deeped and debugged the call to "dict_lookup" >>> performed by doveadm. Indeed the client gets the proper string from the >>> socket and to my surprise, it is properly unescaped. >>> >>> Then, in "client_dict_lookup" ("lib-dict/dict-client.c"), the call to >>> "p_strdup" returns an empty string (null byte set at the target address). >>> >>> Before the call to the dict "->lookup" attribute (client_dict_lookup): >>> >>> RAX: 0x7ffff73a37c0 (push r14) >>> RBX: 0x6831b8 ("priv/reply_body") >>> RCX: 0x7fffffffe240 --> 0x682a60 --> 0x6831b8 ("priv/reply_body") >>> RDX: 0x6831b8 ("priv/reply_body") >>> RSI: 0x683288 --> 0x7ffff7653120 --> 0x7ffff73ea620 ([...]) >>> RDI: 0x690ad0 --> 0x7ffff7400713 --> 0x75250079786f7270 ('proxy') >>> >>> 0x7ffff73a1f10 <dict_lookup+32>: mov rcx,r11 (value_r) >>> 0x7ffff73a1f13 <dict_lookup+35>: mov rdx,r8 (key) >>> 0x7ffff73a1f16 <dict_lookup+38>: mov rsi,r10 (pool) >>> 0x7ffff73a1f19 <dict_lookup+41>: mov rdi,r9 (dict) >>> 0x7ffff73a1f1c <dict_lookup+44>: add rsp,0x8 >>> => 0x7ffff73a1f20 <dict_lookup+48>: jmp rax >>> >>> Before the call to p_strdup in "client_dict_lookup": >>> >>> RSI: 0x6832d8 ("test\r\ntest") (lookup.result.value) >>> RDI: 0x683288 --> 0x7ffff7653120 --> [...] (pool) >>> RAX: 0x0 (result) >>> >>> 0x7ffff73a384f: nop >>> 0x7ffff73a3850: mov rsi,QWORD PTR [rsp+0x8] >>> 0x7ffff73a3855: mov rdi,r14 >>> => 0x7ffff73a3858: call 0x7ffff736d3c0 <p_strdup at plt> >>> 0x7ffff73a385d: mov QWORD PTR [r13+0x0],rax >>> 0x7ffff73a3861: mov rsi,QWORD PTR [rsp+0x18] >>> 0x7ffff73a3866: xor rsi,QWORD PTR fs:0x28 >>> 0x7ffff73a386f: mov eax,ebx >>> >>> After the call: >>> >>> 0x7ffff73a3850: mov rsi,QWORD PTR [rsp+0x8] >>> 0x7ffff73a3855: mov rdi,r14 >>> 0x7ffff73a3858: call 0x7ffff736d3c0 <p_strdup at plt> >>> => 0x7ffff73a385d: mov QWORD PTR [r13+0x0],rax >>> 0x7ffff73a3861: mov rsi,QWORD PTR [rsp+0x18] >>> 0x7ffff73a3866: xor rsi,QWORD PTR fs:0x28 >>> 0x7ffff73a386f: mov eax,ebx >>> 0x7ffff73a3871: jne 0x7ffff73a38da >>> >>> RSI: 0x0 >>> RDI: 0x6832d8 --> 0x0 >>> RAX: 0x6832d8 --> 0x0 (result) >>> >>> It is worth noting that I can reproduce the exact same execution flow >>> with a non-multiline result string (lookup.result.value) that is >>> properly copied by "p_strdup" and returned in RAX, then displayed by >>> doveadm. >>> >>> I am not familiar with the pooling mechanism hidden behind the call to >>> p_strdump and not quite sure why this behaviour is emerging. Maybe I am >>> even miles away from an understanding of the issue here, but it sounds >>> to me like something is wrong in the way "p_strdup" performs the copy. >>> >>> Hope this helps, >>> kaiyou. >>> >>> >>>
Pierre Jaury
2016-Oct-17 13:14 UTC
Dict proxy client returning empty string instead of multiline string
Okay, it seems to me that the bug is due to "t_str_tabunescape" using the unsafe datastack ("t_strdup_noconst") while the string is actually returned in an async callback. Before it is handled by "client_dict_lookup", "client_dict_wait" actually fires some IO loops that are more than likely to call "t_pop" and free/flush the result string (I checked, it does call "t_pop" a couple times indeed). Maybe it would be safer to use a standard datastack pool when unescaping a string in that context. I could work on a patch that would: - add an optional "pool" attribute to the "client_dict_cmd" structure, - pass the pool to the async lookup function, - use the pool when escaping strings that should survive the callback chain What do you think? Regards, kaiyou On 10/17/2016 09:52 AM, Pierre Jaury wrote:> While trying to isolate properly and reproduce, I was able to trigger > the same bug with the following code: > > struct dict *dict; > char* dict_uri = "proxy::sieve"; > char* key = "priv/key"; > char* username = "admin at domain.tld"; > char* value, error; > > dict_drivers_register_builtin(); > dict_init(dict_uri, DICT_DATA_TYPE_STRING, username, > doveadm_settings->base_dir, &dict, &error); > dict_lookup(dict, pool_datastack_create(), key, &value); > printf(">%s\n", value); // outputs an empty string > dict_deinit(&dict); > > I trimmed it to the bare minimal string manipulation functions involved > but cannot reproduce in that case: > > pool_t pool = pool_datastack_create(); > > char* s1 = "test\001n\001rtest"; > char* s2 = t_str_tabunescape(s1); > char* s3 = p_strdup(pool, s2); > > printf("1>%s\n", s1); > printf("2>%s\n", s2); > printf("3>%s\n", s3); // all three output the string with NL and CR > > Maybe I am missing a function call in the process or maybe the issue is > related to the way unescaping is performed in the async callback > function in "dict-client.c", or maybe even some other edge case. > > Finally, I was able to run the first snippet without bug by removing the > string duplication in "t_str_tabunescape" (which I realize is not a > proper solution), or by explicitely using the following pool: > > return str_tabunescape(p_strdup(pool_datastack_create(), str)); > > > Hope this helps. > > kaiyou > > > On 10/17/2016 07:51 AM, Aki Tuomi wrote: >> Hi! >> >> This does sound like a bug, we'll have look. >> >> Aki >> >> >> On 17.10.2016 01:26, Pierre Jaury wrote: >>> I dived a little bit further into the rabbit hole, up to the point where >>> debugging has become unpracticle but I still haven't found the root >>> cause for sure. >>> >>> I read most of the code for "p_strdup" based on datastack memory pools >>> (which are used for dictionary lookups both with doveadm and by extdata) >>> and it seems ok. Still, after "t_malloc_real" is called in "t_malloc0", >>> the allocated buffer has the same address as the source string. >>> >>> The only sensible explanation I can come up with is that during >>> unescaping, strings are not allocated properly, leading to the memory >>> pool reusing the string address and zeroing it in the process before the >>> string copy operation. >>> >>> I will follow on this path tomorrow, any lead is more than welcome. >>> >>> kaiyou. >>> >>> On 10/16/2016 11:16 PM, Pierre Jaury wrote: >>>> Hello, >>>> >>>> I am using a dict proxy for my sieve extdata plugin to access some >>>> fields from an SQLite database (autoreply text and other >>>> database-configured items). >>>> >>>> All tests are performed against version 2.2.25. >>>> >>>> $ dovecot --version >>>> 2.2.25 (7be1766) >>>> >>>> My configuration looks like: >>>> >>>> dict { >>>> sieve = sqlite:/etc/dovecot/pigeonhole-sieve.dict >>>> } >>>> >>>> [...] >>>> sieve_extdata_dict_uri = proxy::sieve >>>> >>>> I am able to read pretty much any attribute without any issue, except >>>> when the value contains a special character like "\r" or "\n". By using >>>> the doveadm dict client, I narrowed it down to the dictionary management >>>> part (either server, protocol or client). >>>> >>>> I was suspecting escaping functions from "lib/strescape.c" (mostly >>>> str_tabescape and its counterpart, used by "lib-dict/client.c"), so I >>>> monitored socket communications. It seems that escaping is done properly >>>> on the server and the socket is not an issue either. >>>> >>>> The following strace dump results from running "doveadm dict get" >>>> against the dict socket: >>>> >>>> connect(8, {sa_family=AF_UNIX, sun_path="..."}, 110) = 0 >>>> fstat(8, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0 >>>> [...] >>>> write(8, "H2\t0\t0\tadmin at domain.tld\tsieve\n", 30) = 30 >>>> [...] >>>> read(8, "Otest\1r\1ntest\n", 8192) = 14 >>>> >>>> Indeed "\1r" and "\1n" are the escape sequences used by >>>> "lib/strescape.c". I went deeped and debugged the call to "dict_lookup" >>>> performed by doveadm. Indeed the client gets the proper string from the >>>> socket and to my surprise, it is properly unescaped. >>>> >>>> Then, in "client_dict_lookup" ("lib-dict/dict-client.c"), the call to >>>> "p_strdup" returns an empty string (null byte set at the target address). >>>> >>>> Before the call to the dict "->lookup" attribute (client_dict_lookup): >>>> >>>> RAX: 0x7ffff73a37c0 (push r14) >>>> RBX: 0x6831b8 ("priv/reply_body") >>>> RCX: 0x7fffffffe240 --> 0x682a60 --> 0x6831b8 ("priv/reply_body") >>>> RDX: 0x6831b8 ("priv/reply_body") >>>> RSI: 0x683288 --> 0x7ffff7653120 --> 0x7ffff73ea620 ([...]) >>>> RDI: 0x690ad0 --> 0x7ffff7400713 --> 0x75250079786f7270 ('proxy') >>>> >>>> 0x7ffff73a1f10 <dict_lookup+32>: mov rcx,r11 (value_r) >>>> 0x7ffff73a1f13 <dict_lookup+35>: mov rdx,r8 (key) >>>> 0x7ffff73a1f16 <dict_lookup+38>: mov rsi,r10 (pool) >>>> 0x7ffff73a1f19 <dict_lookup+41>: mov rdi,r9 (dict) >>>> 0x7ffff73a1f1c <dict_lookup+44>: add rsp,0x8 >>>> => 0x7ffff73a1f20 <dict_lookup+48>: jmp rax >>>> >>>> Before the call to p_strdup in "client_dict_lookup": >>>> >>>> RSI: 0x6832d8 ("test\r\ntest") (lookup.result.value) >>>> RDI: 0x683288 --> 0x7ffff7653120 --> [...] (pool) >>>> RAX: 0x0 (result) >>>> >>>> 0x7ffff73a384f: nop >>>> 0x7ffff73a3850: mov rsi,QWORD PTR [rsp+0x8] >>>> 0x7ffff73a3855: mov rdi,r14 >>>> => 0x7ffff73a3858: call 0x7ffff736d3c0 <p_strdup at plt> >>>> 0x7ffff73a385d: mov QWORD PTR [r13+0x0],rax >>>> 0x7ffff73a3861: mov rsi,QWORD PTR [rsp+0x18] >>>> 0x7ffff73a3866: xor rsi,QWORD PTR fs:0x28 >>>> 0x7ffff73a386f: mov eax,ebx >>>> >>>> After the call: >>>> >>>> 0x7ffff73a3850: mov rsi,QWORD PTR [rsp+0x8] >>>> 0x7ffff73a3855: mov rdi,r14 >>>> 0x7ffff73a3858: call 0x7ffff736d3c0 <p_strdup at plt> >>>> => 0x7ffff73a385d: mov QWORD PTR [r13+0x0],rax >>>> 0x7ffff73a3861: mov rsi,QWORD PTR [rsp+0x18] >>>> 0x7ffff73a3866: xor rsi,QWORD PTR fs:0x28 >>>> 0x7ffff73a386f: mov eax,ebx >>>> 0x7ffff73a3871: jne 0x7ffff73a38da >>>> >>>> RSI: 0x0 >>>> RDI: 0x6832d8 --> 0x0 >>>> RAX: 0x6832d8 --> 0x0 (result) >>>> >>>> It is worth noting that I can reproduce the exact same execution flow >>>> with a non-multiline result string (lookup.result.value) that is >>>> properly copied by "p_strdup" and returned in RAX, then displayed by >>>> doveadm. >>>> >>>> I am not familiar with the pooling mechanism hidden behind the call to >>>> p_strdump and not quite sure why this behaviour is emerging. Maybe I am >>>> even miles away from an understanding of the issue here, but it sounds >>>> to me like something is wrong in the way "p_strdup" performs the copy. >>>> >>>> Hope this helps, >>>> kaiyou. >>>> >>>> >>>>
Possibly Parallel Threads
- Dict proxy client returning empty string instead of multiline string
- Dict proxy client returning empty string instead of multiline string
- Dict proxy client returning empty string instead of multiline string
- Dict proxy client returning empty string instead of multiline string
- Dict proxy client returning empty string instead of multiline string