Dict proxy client returning empty string instead of multiline string

Mon Oct 17 07:52:49 UTC 2016

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.
>>>
>>>
>>>