Hi Daniel,

On Thu, Dec 15, 2016 at 9:36 PM, Daniel Wagner <wagi@monom.org> wrote:
Hi Shrikant,

On 12/15/2016 01:47 PM, Shrikant Bobade wrote:
Reading symbols from /usr/sbin/connmand...Reading symbols from /usr/sbin/.debug/connmand...done.
done.
(gdb) r -d -n
Starting program: /usr/sbin/connmand -d -n
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/libthread_db.so.1".
^C
Program received signal SIGINT, Interrupt.
0x76c3193c in syscall () from /lib/libc.so.6
(gdb) bt
#0  0x76c3193c in syscall () from /lib/libc.so.6
#1  0x76e272a8 in force_getrandom (flags=0, buflen=<optimized out>, buf=<optimized out>) at ../../../gnutls-3.5.3/lib/nettle/rnd-linux.c:80
#2  _rnd_get_system_entropy_getrandom (_rnd=<optimized out>, size=<optimized out>) at ../../../gnutls-3.5.3/lib/nettle/rnd-linux.c:98
#3  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
#4  0x76e244ac in wrap_nettle_rnd_init (ctx=<optimized out>) at ../../../gnutls-3.5.3/lib/nettle/rnd.c:234
#5  0x76d72a28 in _gnutls_rnd_init () at ../../gnutls-3.5.3/lib/random.c:49
#6  0x76d64dfc in _gnutls_global_init (constructor=constructor@entry=1) at ../../gnutls-3.5.3/lib/global.c:307
#7  0x76d3d948 in lib_init () at ../../gnutls-3.5.3/lib/global.c:504
#8  0x76fdf2dc in call_init.part () from /lib/ld-linux-armhf.so.3
#9  0x76fdf438 in _dl_init () from /lib/ld-linux-armhf.so.3
#10 0x76fcfac4 in _dl_start_user () from /lib/ld-linux-armhf.so.3
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb)

 Unfortunately, the ConnMan part is missing. But from our discussion I expect gnutls is involved doing the wispr stuff. Though as I said, I don't understand why this blocks the IP address assignment.

Connman strace during zero entropy on my target.
:~# cat /proc/sys/kernel/random/entropy_avail
0
:~# strace /usr/sbin/connmand -n                                                                                                                                                
execve("/usr/sbin/connmand", ["/usr/sbin/connmand", "-n"], [/* 13 vars */]) = 0
brk(NULL)                               = 0xc4000
uname({sysname="Linux", nodename="ls1021atwr", ...}) = 0
mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x76f8d000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=18029, ...}) = 0
mmap2(NULL, 18029, PROT_READ, MAP_PRIVATE, 3, 0) = 0x76f88000
close(3)                                = 0
open("/usr/lib/libglib-2.0.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0@U\1\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=990936, ...}) = 0
mmap2(NULL, 1056584, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x76e5e000
mprotect(0x76f4f000, 65536, PROT_NONE)  = 0
mmap2(0x76f5f000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xf1000) = 0x76f5f000
close(3)                                = 0
open("/usr/lib/libdbus-1.so.3", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0<\252\0\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=262504, ...}) = 0
mmap2(NULL, 326760, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x76e0e000
mprotect(0x76e4d000, 65536, PROT_NONE)  = 0
mmap2(0x76e5d000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x3f000) = 0x76e5d000
close(3)                                = 0
open("/usr/lib/libxtables.so.11", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0`#\0\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=39588, ...}) = 0
mmap2(NULL, 105344, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x76df4000
mprotect(0x76dfe000, 61440, PROT_NONE)  = 0
mmap2(0x76e0d000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x9000) = 0x76e0d000
close(3)                                = 0
open("/usr/lib/libgnutls.so.30", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0008\233\1\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=1242976, ...}) = 0
mmap2(NULL, 1310148, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x76cb4000
mprotect(0x76ddc000, 65536, PROT_NONE)  = 0
mmap2(0x76dec000, 32768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x128000) = 0x76dec000
close(3)                                = 0
open("/lib/libresolv.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0008%\0\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=103452, ...}) = 0
mmap2(NULL, 153528, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x76c8e000
mprotect(0x76ca1000, 61440, PROT_NONE)  = 0
mmap2(0x76cb0000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x12000) = 0x76cb0000
mmap2(0x76cb2000, 6072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x76cb2000
close(3)                                = 0
open("/lib/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\234\n\0\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=28084, ...}) = 0
mmap2(NULL, 82140, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x76c79000
mprotect(0x76c7d000, 61440, PROT_NONE)  = 0
mmap2(0x76c8c000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x3000) = 0x76c8c000
close(3)                                = 0
open("/lib/librt.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\3\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\0\27\0\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=42832, ...}) = 0
mmap2(NULL, 90640, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x76c62000
mprotect(0x76c68000, 61440, PROT_NONE)  = 0
mmap2(0x76c77000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x5000) = 0x76c77000
close(3)                                = 0
open("/lib/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\200\315\0\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0664, st_size=287868, ...}) = 0
mmap2(NULL, 178672, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x76c36000
mprotect(0x76c52000, 61440, PROT_NONE)  = 0
mmap2(0x76c61000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1b000) = 0x76c61000
close(3)                                = 0
open("/lib/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0,h\1\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=1686056, ...}) = 0
mmap2(NULL, 1303888, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x76af7000
mprotect(0x76c21000, 61440, PROT_NONE)  = 0
mmap2(0x76c30000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x129000) = 0x76c30000
mmap2(0x76c33000, 9552, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x76c33000
close(3)                                = 0
open("/usr/lib/libpcre.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\274\16\0\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=260108, ...}) = 0
mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x76f86000
mmap2(NULL, 324196, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x76aa7000
mprotect(0x76ae6000, 65536, PROT_NONE)  = 0
mmap2(0x76af6000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x3f000) = 0x76af6000
close(3)                                = 0
open("/lib/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\3\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\34I\0\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=152184, ...}) = 0
mmap2(NULL, 164428, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x76a7e000
mprotect(0x76a94000, 61440, PROT_NONE)  = 0
mmap2(0x76aa3000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x15000) = 0x76aa3000
mmap2(0x76aa5000, 4684, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x76aa5000
close(3)                                = 0
open("/lib/libsystemd.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\340\233\0\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=473700, ...}) = 0
mmap2(NULL, 539928, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x769fa000
mprotect(0x76a6b000, 65536, PROT_NONE)  = 0
mmap2(0x76a7b000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x71000) = 0x76a7b000
close(3)                                = 0
open("/lib/libz.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0p\31\0\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=75948, ...}) = 0
mmap2(NULL, 139976, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x769d7000
mprotect(0x769e9000, 65536, PROT_NONE)  = 0
mmap2(0x769f9000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x12000) = 0x769f9000
close(3)                                = 0
open("/usr/lib/libidn.so.11", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\370\35\0\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=196936, ...}) = 0
mmap2(NULL, 260960, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x76997000
mprotect(0x769c7000, 61440, PROT_NONE)  = 0
mmap2(0x769d6000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2f000) = 0x769d6000
close(3)                                = 0
open("/usr/lib/libnettle.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\300o\0\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=218220, ...}) = 0
mmap2(NULL, 282268, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x76952000
mprotect(0x76987000, 61440, PROT_NONE)  = 0
mmap2(0x76996000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x34000) = 0x76996000
close(3)                                = 0
open("/usr/lib/libhogweed.so.4", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0000W\0\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=176904, ...}) = 0
mmap2(NULL, 240932, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x76917000
mprotect(0x76942000, 61440, PROT_NONE)  = 0
mmap2(0x76951000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2a000) = 0x76951000
close(3)                                = 0
open("/usr/lib/libgmp.so.10", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0 \223\0\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=381688, ...}) = 0
mmap2(NULL, 445800, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x768aa000
mprotect(0x76907000, 61440, PROT_NONE)  = 0
mmap2(0x76916000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x5c000) = 0x76916000
close(3)                                = 0
open("/lib/libcap.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0t\20\0\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=15544, ...}) = 0
mmap2(NULL, 79628, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x76896000
mprotect(0x7689a000, 61440, PROT_NONE)  = 0
mmap2(0x768a9000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x3000) = 0x768a9000
close(3)                                = 0
open("/lib/libm.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\250>\0\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=545652, ...}) = 0
mmap2(NULL, 520352, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x76816000
mprotect(0x76885000, 61440, PROT_NONE)  = 0
mmap2(0x76894000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6e000) = 0x76894000
close(3)                                = 0
open("/usr/lib/liblzma.so.5", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0X#\0\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=129688, ...}) = 0
mmap2(NULL, 193712, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x767e6000
mprotect(0x76805000, 65536, PROT_NONE)  = 0
mmap2(0x76815000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1f000) = 0x76815000
close(3)                                = 0
mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x76f84000
set_tls(0x76f85570, 0x76f85cb8, 0x76f90050, 0x76f85570, 0x76f90050) = 0
mprotect(0x76c30000, 8192, PROT_READ)   = 0
mprotect(0x76aa3000, 4096, PROT_READ)   = 0
mprotect(0x76894000, 4096, PROT_READ)   = 0
mprotect(0x76cb0000, 4096, PROT_READ)   = 0
mprotect(0x76c77000, 4096, PROT_READ)   = 0
mprotect(0x76a7b000, 8192, PROT_READ)   = 0
mprotect(0x76c8c000, 4096, PROT_READ)   = 0
mprotect(0x76f8f000, 4096, PROT_READ)   = 0
munmap(0x76f88000, 18029)               = 0
set_tid_address(0x76f85118)             = 813
set_robust_list(0x76f85120, 12)         = 0
rt_sigaction(SIGRTMIN, {0x76a8222c, [], SA_RESTORER|SA_SIGINFO, 0x76b233d0}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {0x76a82328, [], SA_RESTORER|SA_RESTART|SA_SIGINFO, 0x76b233d0}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
ugetrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
brk(NULL)                               = 0xc4000
brk(0xe5000)                            = 0xe5000
getrandom(0x7ef1ac40, 1, GRND_NONBLOCK) = -1 EAGAIN (Resource temporarily unavailable)
getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 0}, ru_stime={0, 10000}, ...}) = 0
getrandom(
execution just stuck at this point..
 

The particular delay of assigning IP addresses was in term of getrandom
hang,
when connmon.service get multiple attempts...during these attempts
minimal entropy available ranging from 10 to 30.. to moved ahead of
getrandom..

 I think I don't really understand what you describe here. Does 'attempt' mean the user/application tries to tell ConnMan establish a connection and this is done using the D-Bus API. Or do you mean the auto connect state machine?
ok, adding the details below..

using systemd as init-manager, with connman.service status check observed no activity for few mins(w.r.to above case of strace getrandom), internally observed during this time connman.service get re-started and we can see new instance of connmand..i.e. attempt
during 2 to 3 attemps/re-start of connman.service when the target entropy reached nearly between 10 to 30 range got the getrandom hang resolved..with further connman execution getting the ip assignment, so actual delay happening during multiple attempts for pass-through of getrandom.

Now to resolve the getrandom hang, used rng-tools, with rngd running via rngd.service(before connman.service) getting available entropy between 3k to 4k, & call to getrandom getting passed easily, so almost no delay in ip assignment from user point of view.
 
 

Thanks,
Daniel


Thanks
Shrikant