Hi Daniel,

On Sat, Dec 31, 2016 at 8:48 PM, Daniel Wagner <wagi@monom.org> wrote:
>
> Hi Shrikant,
>
> On 12/29/2016 04:05 PM, Shrikant Bobade wrote:
>>
>> Breakpoint @ _rnd_get_system_entropy_getrandom (_rnd=0x7efffc78, size=32)
>>
>> bt
>> #0  _rnd_get_system_entropy_getrandom (_rnd=0x7efffc78, size=32) at
>> ../../../gnutls-3.5.3/lib/nettle/rnd-linux.c:98
>> #1  0x76e24344 in do_device_source (init=init@entry=1,
>> event=event@entry=0x7efffcdc, ctx=0x76e62a38 <rnd_ctx>) at
>> ../../../gnutls-3.5.3/lib/nettle/rnd.c:132
>> #2  0x76e244ac in wrap_nettle_rnd_init (ctx=<optimized out>) at
>> ../../../gnutls-3.5.3/lib/nettle/rnd.c:234
>> #3  0x76d72a28 in _gnutls_rnd_init () at ../../gnutls-3.5.3/lib/random.c:49
>> #4  0x76d64dfc in _gnutls_global_init (constructor=constructor@entry=1)
>> at ../../gnutls-3.5.3/lib/global.c:307
>
>
> I am pretty sure we end here from gweb.c::connect_session_transport(). If you start ConnMan with
>
> CONNMAN_WEB_DEBUG=1 connmand -n -d

Tried running with
CONNMAN_WEB_DEBUG=1 connmand -n -d
when available entropy value to zero.

:~# cat /proc/sys/kernel/random/entropy_avail
0
:~#
root@ls1021atwr:~# CONNMAN_WEB_DEBUG=1 ./connmand -n -d

like earlier it just hangs here.. didn't got any debug message..

cross-checked the executed comman with entropy and found getting the debug logs..

seems the connmand hangs much earlier..

>
> you would see
>
> WEB: gweb/gweb.c:connect_session_transport() web 0x62c2e0 using TLS encryption
>
> right before you block.
>
> Looking at the gnutls code I see:
>
> static int force_getrandom(void *buf, size_t buflen, unsigned int flags)
> {
>         int left = buflen;
>         int ret;
>         uint8_t *p = buf;
>
>         while (left > 0) {
>                 ret = getrandom(p, left, flags);
>                 if (ret == -1) {
>                         if (errno != EINTR)
>                                 return ret;
>                 }
>
>                 if (ret > 0) {
>                         left -= ret;
>                         p += ret;
>                 }
>         }
>
>         return buflen;
> }
>
> static int _rnd_get_system_entropy_getrandom(void* _rnd, size_t size)
> {
>         int ret;
>         ret = force_getrandom(_rnd, size, 0);
>         if (ret == -1) {
>                 int e = errno;
>                 gnutls_assert();
>                 _gnutls_debug_log
>                         ("Failed to use getrandom: %s\n",
>                                          strerror(e));
>                 return GNUTLS_E_RANDOM_DEVICE_ERROR;
>         }
>
>         return 0;
> }
>
> And the manual page on getrandom tells us:
>
> SYNOPSIS
>        #include <linux/random.h>
>
>        int getrandom(void *buf, size_t buflen, unsigned int flags);
>
> DESCRIPTION
>        The  getrandom()  system  call fills the buffer pointed to by
>        buf with up to buflen random bytes.  These bytes can be  used
>        to  seed  user-space  random number generators or for crypto‐
>        graphic purposes.
>
>        getrandom() relies on entropy gathered  from  device  drivers
>        and  other  sources  of  environmental  noise.  Unnecessarily
>        reading large quantities of data will have a negative  impact
>        on  other  users of the /dev/random and /dev/urandom devices.
>        Therefore, getrandom() should not be  used  for  Monte  Carlo
>        simulations  or  other  programs/algorithms  which  are doing
>        probabilistic sampling.
>
>        By default, getrandom() draws entropy from  the  /dev/urandom
>        pool.   This  behavior can be changed via the flags argument.
>        If the /dev/urandom pool has been initialized, reads of up to
>        256  bytes  will always return as many bytes as requested and
>        will not be interrupted by signals.  No such guarantees apply
>        for  larger buffer sizes.  For example, if the call is inter‐
>        rupted by a signal handler, it may return a partially  filled
>        buffer,  or  fail  with the error EINTR.  If the pool has not
>        yet been initialized, then the call blocks, unless  GRND_NON‐
>        BLOCK is specified in flags.
>
>        The  flags  argument  is  a bit mask that can contain zero or
>        more of the following values ORed together:
>
>        GRND_RANDOM
>               If this bit is set, then random bytes are  drawn  from
>               the /dev/random pool instead of the /dev/urandom pool.
>               The /dev/random pool is limited based on  the  entropy
>               that can be obtained from environmental noise.  If the
>               number of available bytes in /dev/random is less  than
>               requested  in buflen, the call returns just the avail‐
>               able random bytes.  If no random bytes are  available,
>               the  behavior depends on the presence of GRND_NONBLOCK
>               in the flags argument.
>
>        GRND_NONBLOCK
>               By default, when reading from /dev/random, getrandom()
>               blocks  if  no  random  bytes  are available, and when
>               reading from /dev/urandom, it blocks  if  the  entropy
>               pool  has  not yet been initialized.  If the GRND_NON‐
>               BLOCK flag is set, then getrandom() does not block  in
>               these  cases,  but instead immediately returns -1 with
>               errno set to EAGAIN.
>
> As gnutls uses it with flags=0, getrandom() will block on reading urandom. So far so good.
>
> I just don't get it why the wispr stuff is running before we have an IP address. It would really help if we get the ConnMan output to see how we end up here (see below how to create the log).

Tried generating logs, but with zero entropy available with these too didn't got debug logs..
:~# CONNMAN_DHCP_DEBUG=1 CONNMAN_DHCPV6_DEBUG=1 ./connmand -d -n

:~# cat /proc/sys/kernel/random/entropy_avail
0
:~# CONNMAN_DHCP_DEBUG=1 CONNMAN_DHCPV6_DEBUG=1 CONNMAN_WEB_DEBUG=1 ./connmand -d -n

:~# cat /proc/sys/kernel/random/entropy_avail
0
:~#



note: with ~3K entropy available the execution is smooth and getting the debug logs.. just cross checked for execution commands.

e.g.
:~# cat /proc/sys/kernel/random/entropy_avail                                                                                                                           
3087
root@ls1021atwr:~#

:~# CONNMAN_WEB_DEBUG=1 ./connmand -n -d   
connmand[833]: Connection Manager version 1.33
connmand[833]: ../connman-1.33/src/dbus.c:__connman_dbus_init()
connmand[833]: ../connman-1.33/src/inotify.c:__connman_inotify_init()
connmand[833]: ../connman-1.33/src/technology.c:__connman_technology_init()
connmand[833]: ../connman-1.33/src/storage.c:storage_load() Loading /var/lib/connman/settings
connmand[833]: ../connman-1.33/src/storage.c:storage_load() Loading /var/lib/connman/settings
connmand[833]: ../connman-1.33/src/notifier.c:__connman_notifier_init()
.
.
got ip assigned

:~# CONNMAN_DHCP_DEBUG=1 CONNMAN_DHCPV6_DEBUG=1 CONNMAN_WEB_DEBUG=1 ./connmand -d -n
connmand[892]: Connection Manager version 1.33
connmand[892]: ../connman-1.33/src/dbus.c:__connman_dbus_init()
connmand[892]: ../connman-1.33/src/inotify.c:__connman_inotify_init()
connmand[892]: ../connman-1.33/src/technology.c:__connman_technology_init()
connmand[892]: ../connman-1.33/src/storage.c:storage_load() Loading /var/lib/connman/settings
connmand[892]: ../connman-1.33/src/storage.c:storage_load() Loading /var/lib/connman/settings
connmand[892]: ../connman-1.33/src/notifier.c:__connman_notifier_init()
connmand[892]: ../connman-1.33/src/agent.c:__connman_agent_init()
connmand[892]: ../connman-1.33/src/service.c:__connman_service_init()
.
.
.
got ip assigned


>
>
>> #5  0x76d3d948 in lib_init () at ../../gnutls-3.5.3/lib/global.c:504
>> #6  0x76fdf2dc in call_init.part () from /lib/ld-linux-armhf.so.3
>> #7  0x76fdf438 in _dl_init () from /lib/ld-linux-armhf.so.3
>> #8  0x76fcfac4 in _dl_start_user () from /lib/ld-linux-armhf.so.3
>> Backtrace stopped: previous frame identical to this frame (corrupt stack?)
>
>
> I played a bit around with tool/wispr and gdb. It never stopped on
> _rnd_get_system_entropy_getrandom(). There was also some strange
> behavior inside gdb. Maybe gnutls does some things which gdb doesn't like too much.
>
>
>>>         CONNMAN_DHCP_DEBUG=1 CONNMAN_DHCPV6_DEBUG=1 ./connman -d -n
>>> ?
>>
>> yes, didn't got any debug info with it...
>> :~#  CONNMAN_DHCP_DEBUG=1 CONNMAN_DHCPV6_DEBUG=1 ./connmand -d -n
>>
>> :~# CONNMAN_DHCP_DEBUG=1 CONNMAN_DHCPV6_DEBUG=1 ./connmand -d -n  &
>> [1] 789
>> :~#
>> :~# pidof connmand
>> 789
>> :~#
>
>
> I am interested in the log output from '-d'. Just pipe the output into a file and upload the file somewhere and post the link here (if the log file is too large)
>
> CONNMAN_DHCP_DEBUG=1 CONNMAN_DHCPV6_DEBUG=1 CONNMAN_WEB_DEBUG=1 ./connmand -d -n 2>&1 > /tmp/connman.log
>
>>> Uuuuuh, I think I found it gdhcp/common.c:
>>>
>>> #define URANDOM "/dev/urandom"
>>> static int random_fd = -1;
>>>
>>> int dhcp_get_random(uint64_t *val)
>>> {
>>>         int r;
>>>
>>>         if (random_fd < 0) {
>>>                 random_fd = open(URANDOM, O_RDONLY);
>>>                 if (random_fd < 0) {
>>>                         r = -errno;
>>>                         *val = random();
>>>
>>>                         return r;
>>>                 }
>>>         }
>>>
>>>         if (read(random_fd, val, sizeof(uint64_t)) < 0) {
>>>                 r = -errno;
>>>                 *val = random();
>>>
>>>                 return r;
>>>         }
>>>
>>>         return 0;
>>> }
>>>
>>> So for a simple test, can you change the define to
>>>
>>> #define URANDOM "/dev/random"
>>>
>>> and see if you still block?
>>
>>
>> prepared the change, observed the first attempt is similar..
>
>
> Okay, so that is not the source of the blocking. But we still should address this.
ok.
>
> Thanks,
> Daniel

Thanks
Shrikant