Azure CPI hangs talking to Azure for > 2 days #93

jim80net · 2016-02-22T21:54:14Z

Azure CPI hangs talking to Azure. In this instance, two threads were dead waiting for a response. We think that it was waiting without somehow triggering a timeout. We're not sure why this was.

# ps -auxfw
vcap     46743  0.0  1.9 148508 67016 ?        S<l  Feb17   0:26 resque-1.25.2: Forked 3530 at 1455954009
vcap      3530  0.0  2.0 622160 72404 ?        S<l  Feb20   1:04  \_ resque-1.25.2: Processing normal since 1455954009 [Bosh::Director::Jobs::CloudCheck::ScanAndFix]
vcap      3560  0.0  0.0  17968  2776 ?        S<   Feb20   0:00      \_ /bin/bash /var/vcap/jobs/cpi/bin/cpi
vcap      3565  0.0  1.0 121396 38480 ?        S<l  Feb20   0:01          \_ ruby /var/vcap/packages/bosh_azure_cpi/bin/azure_cpi /var/vcap/jobs/cpi/config/cpi.json
vcap     46748  0.0  1.8 148932 65444 ?        S<l  Feb17   0:25 resque-1.25.2: Forked 3323 at 1455953292
vcap      3323  0.0  1.9 622076 70436 ?        S<l  Feb20   1:04  \_ resque-1.25.2: Processing normal since 1455953292 [Bosh::Director::Jobs::CloudCheck::ScanAndFix]
vcap      3347  0.0  0.0  17968  2804 ?        S<   Feb20   0:00      \_ /bin/bash /var/vcap/jobs/cpi/bin/cpi
vcap      3352  0.0  1.0 121388 38636 ?        S<l  Feb20   0:01          \_ ruby /var/vcap/packages/bosh_azure_cpi/bin/azure_cpi /var/vcap/jobs/cpi/config/cpi.json


root@c89bf596-a6ba-4cd7-a72a-141b993ad445:~# strace -vfFp 3352
Process 3352 attached with 2 threads
[pid  3354] restart_syscall(<... resuming interrupted call ...> <unfinished ...>
[pid  3352] ppoll([{fd=7, events=POLLIN}], 1, NULL, NULL, 8^CProcess 3352 detached
 <detached ...>
Process 3354 detached

root@c89bf596-a6ba-4cd7-a72a-141b993ad445:~# lsof -p 3352
COMMAND  PID USER   FD   TYPE    DEVICE SIZE/OFF      NODE NAME
ruby    3352 vcap  cwd    DIR      8,18     4096   1575493 /var/vcap/data/packages/director/50bccec23f808dbeb00211e81b35f92455d0d11e.1-fcd8ee20028896bb1a9bab5010bc22bd2366a1ab/gem_home/ruby/2.1.0
...
ruby    3352 vcap    7u  IPv4 268242816      0t0       TCP 10.10.0.7:45423->157.55.80.182:https (ESTABLISHED)
root@c89bf596-a6ba-4cd7-a72a-141b993ad445:~#


root@c89bf596-a6ba-4cd7-a72a-141b993ad445:~# gdb /var/vcap/packages/ruby_azure_cpi/bin/ruby 3352
GNU gdb (Ubuntu 7.7.1-0ubuntu5~14.04.2) 7.7.1
Copyright (C) 2014 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /var/vcap/packages/ruby_azure_cpi/bin/ruby...(no debugging symbols found)...done.
Attaching to program: /var/vcap/data/packages/ruby_azure_cpi/3db71123fb72f5ec81955710b2e89e2cbbd8aca0.1-c75c4d3821bf906b729bf1f5930ae9841cecd87a/bin/ruby, process 3352
Reading symbols from /lib/x86_64-linux-gnu/libpthread.so.0...(no debugging symbols found)...done.
[New LWP 3354]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Loaded symbols for /lib/x86_64-linux-gnu/libpthread.so.0
Reading symbols from /lib/x86_64-linux-gnu/libdl.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib/x86_64-linux-gnu/libdl.so.2
Reading symbols from /lib/x86_64-linux-gnu/libcrypt.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib/x86_64-linux-gnu/libcrypt.so.1
Reading symbols from /lib/x86_64-linux-gnu/libm.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib/x86_64-linux-gnu/libm.so.6
Reading symbols from /lib/x86_64-linux-gnu/libc.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib/x86_64-linux-gnu/libc.so.6
Reading symbols from /lib64/ld-linux-x86-64.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/ld-linux-x86-64.so.2
Reading symbols from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/enc/encdb.so...(no debugging symbols found)...done.
Loaded symbols for /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/enc/encdb.so
Reading symbols from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/enc/trans/transdb.so...(no debugging symbols found)...done.
Loaded symbols for /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/enc/trans/transdb.so
Reading symbols from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/thread.so...(no debugging symbols found)...done.
Loaded symbols for /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/thread.so
Reading symbols from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/pathname.so...(no debugging symbols found)...done.
Loaded symbols for /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/pathname.so
Reading symbols from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/io/console.so...(no debugging symbols found)...done.
Loaded symbols for /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/io/console.so
Reading symbols from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/etc.so...(no debugging symbols found)...done.
Loaded symbols for /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/etc.so
Reading symbols from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/digest/sha1.so...(no debugging symbols found)...done.
Loaded symbols for /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/digest/sha1.so
Reading symbols from /lib/x86_64-linux-gnu/libcrypto.so.1.0.0...(no debugging symbols found)...done.
Loaded symbols for /lib/x86_64-linux-gnu/libcrypto.so.1.0.0
Reading symbols from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/digest.so...(no debugging symbols found)...done.
Loaded symbols for /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/digest.so
Reading symbols from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/socket.so...(no debugging symbols found)...done.
Loaded symbols for /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/socket.so
Reading symbols from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/zlib.so...(no debugging symbols found)...done.
Loaded symbols for /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/zlib.so
Reading symbols from /lib/x86_64-linux-gnu/libz.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib/x86_64-linux-gnu/libz.so.1
Reading symbols from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/stringio.so...(no debugging symbols found)...done.
Loaded symbols for /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/stringio.so
Reading symbols from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/date_core.so...(no debugging symbols found)...done.
Loaded symbols for /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/date_core.so
Reading symbols from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/fcntl.so...(no debugging symbols found)...done.
Loaded symbols for /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/fcntl.so
Reading symbols from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/openssl.so...(no debugging symbols found)...done.
Loaded symbols for /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/openssl.so
Reading symbols from /lib/x86_64-linux-gnu/libssl.so.1.0.0...(no debugging symbols found)...done.
Loaded symbols for /lib/x86_64-linux-gnu/libssl.so.1.0.0
Reading symbols from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/strscan.so...(no debugging symbols found)...done.
Loaded symbols for /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/strscan.so
Reading symbols from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/psych.so...(no debugging symbols found)...done.
Loaded symbols for /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/psych.so
Reading symbols from /var/vcap/packages/bosh_azure_cpi/vendor/bundle/ruby/2.1.0/extensions/x86_64-linux/2.1.0-static/json-1.8.3/json/ext/parser.so...(no debugging symbols found)...done.
Loaded symbols for /var/vcap/packages/bosh_azure_cpi/vendor/bundle/ruby/2.1.0/extensions/x86_64-linux/2.1.0-static/json-1.8.3/json/ext/parser.so
Reading symbols from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/enc/utf_16be.so...(no debugging symbols found)...done.
Loaded symbols for /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/enc/utf_16be.so
Reading symbols from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/enc/utf_16le.so...(no debugging symbols found)...done.
Loaded symbols for /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/enc/utf_16le.so
Reading symbols from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/enc/utf_32be.so...(no debugging symbols found)...done.
Loaded symbols for /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/enc/utf_32be.so
Reading symbols from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/enc/utf_32le.so...(no debugging symbols found)...done.
Loaded symbols for /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/enc/utf_32le.so
Reading symbols from /var/vcap/packages/bosh_azure_cpi/vendor/bundle/ruby/2.1.0/extensions/x86_64-linux/2.1.0-static/json-1.8.3/json/ext/generator.so...(no debugging symbols found)...done.
Loaded symbols for /var/vcap/packages/bosh_azure_cpi/vendor/bundle/ruby/2.1.0/extensions/x86_64-linux/2.1.0-static/json-1.8.3/json/ext/generator.so
Reading symbols from /var/vcap/packages/bosh_azure_cpi/vendor/bundle/ruby/2.1.0/extensions/x86_64-linux/2.1.0-static/yajl-ruby-1.2.1/yajl/yajl.so...(no debugging symbols found)...done.
Loaded symbols for /var/vcap/packages/bosh_azure_cpi/vendor/bundle/ruby/2.1.0/extensions/x86_64-linux/2.1.0-static/yajl-ruby-1.2.1/yajl/yajl.so
Reading symbols from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/digest/md5.so...(no debugging symbols found)...done.
Loaded symbols for /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/digest/md5.so
Reading symbols from /var/vcap/packages/bosh_azure_cpi/vendor/bundle/ruby/2.1.0/extensions/x86_64-linux/2.1.0-static/nokogiri-1.6.6.2/nokogiri/nokogiri.so...done.
Loaded symbols for /var/vcap/packages/bosh_azure_cpi/vendor/bundle/ruby/2.1.0/extensions/x86_64-linux/2.1.0-static/nokogiri-1.6.6.2/nokogiri/nokogiri.so
Reading symbols from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/racc/cparse.so...(no debugging symbols found)...done.
Loaded symbols for /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/racc/cparse.so
Reading symbols from /usr/lib/x86_64-linux-gnu/gconv/CP932.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/x86_64-linux-gnu/gconv/CP932.so
Reading symbols from /lib/x86_64-linux-gnu/libnss_files.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib/x86_64-linux-gnu/libnss_files.so.2
Reading symbols from /lib/x86_64-linux-gnu/libnss_dns.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib/x86_64-linux-gnu/libnss_dns.so.2
Reading symbols from /lib/x86_64-linux-gnu/libresolv.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib/x86_64-linux-gnu/libresolv.so.2
0x00007fefc7b341ef in ppoll () from /lib/x86_64-linux-gnu/libc.so.6
(gdb) t a a bt

Thread 2 (Thread 0x7fefc898c700 (LWP 3354)):
#0  0x00007fefc7b3412d in poll () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x000055dff179e72e in timer_thread_sleep ()
#2  0x000055dff179e7d9 in thread_timer ()
#3  0x00007fefc8557182 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#4  0x00007fefc7b4147d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 1 (Thread 0x7fefc8983740 (LWP 3352)):
#0  0x00007fefc7b341ef in ppoll () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x000055dff17a3f53 in rb_wait_for_single_fd ()
#2  0x000055dff17a3bbc in rb_thread_wait_fd_rw ()
#3  0x000055dff17a3beb in rb_thread_wait_fd ()
#4  0x000055dff16705e4 in rb_io_wait_readable ()
#5  0x00007fefc57752fc in ossl_start_ssl () from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/openssl.so
#6  0x00007fefc57753dd in ossl_ssl_connect () from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/x86_64-linux/openssl.so
#7  0x000055dff177d24b in call_cfunc_0 ()
#8  0x000055dff177ddcf in vm_call_cfunc_with_frame ()
#9  0x000055dff177dedc in vm_call_cfunc ()
#10 0x000055dff177e87c in vm_call_method ()
#11 0x000055dff177f10b in vm_call_general ()
#12 0x000055dff17829ae in vm_exec_core ()
#13 0x000055dff1792a67 in vm_exec ()
#14 0x000055dff178b1ed in vm_call0_body ()
#15 0x000055dff178ad60 in vm_call0 ()
#16 0x000055dff178b85b in rb_call0 ()
#17 0x000055dff178c26e in rb_call ()
#18 0x000055dff178cb6a in rb_funcallv ()
#19 0x000055dff164b614 in rb_obj_call_init ()
#20 0x000055dff1699e88 in rb_class_new_instance ()
#21 0x000055dff177d220 in call_cfunc_m1 ()
#22 0x000055dff177ddcf in vm_call_cfunc_with_frame ()
#23 0x000055dff177dedc in vm_call_cfunc ()
#24 0x000055dff177e87c in vm_call_method ()
#25 0x000055dff177f10b in vm_call_general ()
---Type <return> to continue, or q <return> to quit---
#26 0x000055dff17829ae in vm_exec_core ()
#27 0x000055dff1792a67 in vm_exec ()
#28 0x000055dff178b1ed in vm_call0_body ()
#29 0x000055dff178ad60 in vm_call0 ()
#30 0x000055dff178b85b in rb_call0 ()
#31 0x000055dff178c26e in rb_call ()
#32 0x000055dff178cb6a in rb_funcallv ()
#33 0x000055dff164b614 in rb_obj_call_init ()
#34 0x000055dff1699e88 in rb_class_new_instance ()
#35 0x000055dff177d220 in call_cfunc_m1 ()
#36 0x000055dff177ddcf in vm_call_cfunc_with_frame ()
#37 0x000055dff177dedc in vm_call_cfunc ()
#38 0x000055dff177e87c in vm_call_method ()
#39 0x000055dff177f10b in vm_call_general ()
#40 0x000055dff17829ae in vm_exec_core ()
#41 0x000055dff1792a67 in vm_exec ()
#42 0x000055dff17911d0 in invoke_block_from_c ()
#43 0x000055dff1791583 in vm_invoke_proc ()
#44 0x000055dff179163b in rb_vm_invoke_proc ()
#45 0x000055dff164ce65 in proc_call ()
#46 0x000055dff177d220 in call_cfunc_m1 ()
#47 0x000055dff177ddcf in vm_call_cfunc_with_frame ()
#48 0x000055dff177dedc in vm_call_cfunc ()
#49 0x000055dff177e87c in vm_call_method ()
#50 0x000055dff177f10b in vm_call_general ()
#51 0x000055dff17829ae in vm_exec_core ()
#52 0x000055dff1792a67 in vm_exec ()
#53 0x000055dff1793bb0 in rb_iseq_eval_main ()
#54 0x000055dff1648da7 in ruby_exec_internal ()
#55 0x000055dff1648ed0 in ruby_exec_node ()
#56 0x000055dff1648ea3 in ruby_run_node ()
#57 0x000055dff1646f02 in main ()
(gdb)
(gdb) call (void) close(1)
(gdb) call (void) close(2)
(gdb) shell tty
/dev/pts/0
(gdb) call (int) open("/dev/pts/0", 2, 0)
$1 = 1
(gdb) call (int) open("/dev/pts/0", 2, 0)
$2 = 2
(gdb) call (void) rb_backtrace()
    from /var/vcap/packages/bosh_azure_cpi/bin/azure_cpi:34:in `<main>'
    from /var/vcap/packages/bosh_azure_cpi/vendor/bundle/ruby/2.1.0/gems/bosh_cpi-1.3100.0/lib/bosh/cpi/cli.rb:70:in `run'
    from /var/vcap/packages/bosh_azure_cpi/vendor/bundle/ruby/2.1.0/gems/bosh_cpi-1.3100.0/lib/bosh/cpi/cli.rb:70:in `call'
    from /var/vcap/packages/bosh_azure_cpi/bin/azure_cpi:26:in `block in <main>'
    from /var/vcap/packages/bosh_azure_cpi/bin/azure_cpi:26:in `new'
    from /var/vcap/packages/bosh_azure_cpi/lib/cloud/azure/cloud.rb:19:in `initialize'
    from /var/vcap/packages/bosh_azure_cpi/lib/cloud/azure/cloud.rb:367:in `init_azure'
    from /var/vcap/packages/bosh_azure_cpi/lib/cloud/azure/cloud.rb:367:in `new'
    from /var/vcap/packages/bosh_azure_cpi/lib/cloud/azure/table_manager.rb:13:in `initialize'
    from /var/vcap/packages/bosh_azure_cpi/lib/cloud/azure/azure_client2.rb:792:in `get_storage_account_keys_by_name'
    from /var/vcap/packages/bosh_azure_cpi/lib/cloud/azure/azure_client2.rb:1013:in `http_post'
    from /var/vcap/packages/bosh_azure_cpi/lib/cloud/azure/azure_client2.rb:861:in `http_get_response'
    from /var/vcap/packages/bosh_azure_cpi/lib/cloud/azure/azure_client2.rb:835:in `get_token'
    from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/net/http.rb:1369:in `request'
    from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/net/http.rb:852:in `start'
    from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/net/http.rb:863:in `do_start'
    from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/net/http.rb:920:in `connect'
    from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/timeout.rb:76:in `timeout'
    from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/net/http.rb:920:in `block in connect'
    from /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/net/http.rb:920:in `connect'
(gdb) quit
A debugging session is active.

    Inferior 1 [process 3352] will be detached.

Quit anyway? (y or n) y
Detaching from program: /var/vcap/data/packages/ruby_azure_cpi/3db71123fb72f5ec81955710b2e89e2cbbd8aca0.1-c75c4d3821bf906b729bf1f5930ae9841cecd87a/bin/ruby, process 3352
root@c89bf596-a6ba-4cd7-a72a-141b993ad445:~#

root@c89bf596-a6ba-4cd7-a72a-141b993ad445:~# kill 3352
root@c89bf596-a6ba-4cd7-a72a-141b993ad445:~# {"result":null,"error":{"type":"Unknown","message":"SIGTERM","ok_to_retry":false},"log":"Rescued Unknown: SIGTERM. backtrace: /var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/net/http.rb:920:in `connect'\n/var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/net/http.rb:920:in `block in connect'\n/var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/timeout.rb:76:in `timeout'\n/var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/net/http.rb:920:in `connect'\n/var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/net/http.rb:863:in `do_start'\n/var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/net/http.rb:852:in `start'\n/var/vcap/packages/ruby_azure_cpi/lib/ruby/2.1.0/net/http.rb:1369:in `request'\n/var/vcap/packages/bosh_azure_cpi/lib/cloud/azure/azure_client2.rb:835:in `get_token'\n/var/vcap/packages/bosh_azure_cpi/lib/cloud/azure/azure_client2.rb:861:in `http_get_response'\n/var/vcap/packages/bosh_azure_cpi/lib/cloud/azure/azure_client2.rb:1013:in `http_post'\n/var/vcap/packages/bosh_azure_cpi/lib/cloud/azure/azure_client2.rb:792:in `get_storage_account_keys_by_name'\n/var/vcap/packages/bosh_azure_cpi/lib/cloud/azure/table_manager.rb:13:in `initialize'\n/var/vcap/packages/bosh_azure_cpi/lib/cloud/azure/cloud.rb:367:in `new'\n/var/vcap/packages/bosh_azure_cpi/lib/cloud/azure/cloud.rb:367:in `init_azure'\n/var/vcap/packages/bosh_azure_cpi/lib/cloud/azure/cloud.rb:19:in `initialize'\n/var/vcap/packages/bosh_azure_cpi/bin/azure_cpi:26:in `new'\n/var/vcap/packages/bosh_azure_cpi/bin/azure_cpi:26:in `block in <main>'\n/var/vcap/packages/bosh_azure_cpi/vendor/bundle/ruby/2.1.0/gems/bosh_cpi-1.3100.0/lib/bosh/cpi/cli.rb:70:in `call'\n/var/vcap/packages/bosh_azure_cpi/vendor/bundle/ruby/2.1.0/gems/bosh_cpi-1.3100.0/lib/bosh/cpi/cli.rb:70:in `run'\n/var/vcap/packages/bosh_azure_cpi/bin/azure_cpi:34:in `<main>'"}


root@c89bf596-a6ba-4cd7-a72a-141b993ad445:~# grep s.version /var/vcap/packages/bosh_azure_cpi/bosh_azure_cpi.gemspec
  s.version       = '2.0.0'

The text was updated successfully, but these errors were encountered:

AbelHu · 2016-02-22T22:03:09Z

@jim80net Thanks for your reporting. I have several questions for you.

Which version are you using?
Could you send your manifest and the task log to me for advanced investigation? My email is chou.hu@microsoft.com.

sedouard · 2016-02-22T22:03:32Z

FYI -

Not sure if this is related but It's known that the azure ruby sdk doesn't have client side timeouts. We hit this issue when working with the storage APIs from less-than-favorable network connection (eg: uploading to an Azure container from an AWS data center).

The resulting symptoms will be what you see -- a deadlock of threads waiting on some some asynchronous web request.

jim80net · 2016-02-24T01:44:16Z

@AbelHu, email sent.

@sedouard Thanks for the +1, glad to see we're not the only ones impacted.

We'd like to see the client side timeout implemented.

landesherr · 2016-02-24T21:20:36Z

Additional info:

When we encountered this problem, we were using CLI Tool version 0.9.15 from our jumpbox on Azure.

AbelHu · 2016-02-24T21:24:02Z

@landesherr Thanks for your information. How did you get the CPI version 0.9.15?

landesherr · 2016-02-24T21:36:54Z

@AbelHu
npm install -g azure-cli

AbelHu · 2016-02-24T21:40:24Z

@landesherr I think you hit a different issue. Iandesherr hit the issue when using BOSH. But you hit the issue when using azure-cli. Could you describe your steps when you hit your issue?

landesherr · 2016-02-24T21:44:45Z

@AbelHu Sorry for the confusion - I was working with @jim80net when we ran into this problem. If I remember correctly, the BOSH job was triggered from the jumpbox.

AbelHu · 2016-02-24T22:04:43Z

@landesherr the BOSH job is triggered from the jumpbox. But BOSH always calls Azure CPI to talk with Azure. azure-cli is only used when you prepare the service principal if you follow our guide. So I need to know how you hit the issue with azure-cli.

landesherr · 2016-02-24T22:38:24Z

@AbelHu For some reason, I thought you were asking for the CLI version we're using (which is totally unrelated to this problem), not CPI version. Serves me right for not paying enough attention. As @jim80net posted above, we were using what appears to be v2.0.0 of the CPI.

AbelHu · 2016-02-24T22:44:48Z

@landesherr Please show me the CPI release link in your bosh.yml. It is similar to the link here.

landesherr · 2016-02-24T22:53:56Z

  - name: bosh-azure-cpi
    version: 6
    git: https://github.com/cloudfoundry-incubator/bosh-azure-cpi-release.git

svrc · 2016-03-14T17:43:59Z

I'm seeing this too with CPI v7. I'll send a log.

AbelHu · 2016-03-21T02:54:19Z

@jim80net @svrc-pivotal Before Ruby v2.3.0, Net::Http.read_timeout is set to 60 seconds by default but Net::Http.open_timeout is set to nil by default. I also find similar gdb backtrace in chef issue #2944 and puppet issue #1570.
I think it is fixed in the PR #109.

AbelHu · 2016-03-21T03:42:50Z

@sedouard I filed an issue #334 for azure-sdk-for-ruby.

AbelHu mentioned this issue Mar 21, 2016

Set open_timeout for HTTP request. #108

Closed

AbelHu closed this as completed in 4391ee3 Mar 21, 2016

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Azure CPI hangs talking to Azure for > 2 days #93

Azure CPI hangs talking to Azure for > 2 days #93

jim80net commented Feb 22, 2016

AbelHu commented Feb 22, 2016

sedouard commented Feb 22, 2016

jim80net commented Feb 24, 2016

landesherr commented Feb 24, 2016

AbelHu commented Feb 24, 2016

landesherr commented Feb 24, 2016

AbelHu commented Feb 24, 2016

landesherr commented Feb 24, 2016

AbelHu commented Feb 24, 2016

landesherr commented Feb 24, 2016

AbelHu commented Feb 24, 2016

landesherr commented Feb 24, 2016

svrc commented Mar 14, 2016

AbelHu commented Mar 21, 2016

AbelHu commented Mar 21, 2016

Azure CPI hangs talking to Azure for > 2 days #93

Azure CPI hangs talking to Azure for > 2 days #93

Comments

jim80net commented Feb 22, 2016

AbelHu commented Feb 22, 2016

sedouard commented Feb 22, 2016

jim80net commented Feb 24, 2016

landesherr commented Feb 24, 2016

AbelHu commented Feb 24, 2016

landesherr commented Feb 24, 2016

AbelHu commented Feb 24, 2016

landesherr commented Feb 24, 2016

AbelHu commented Feb 24, 2016

landesherr commented Feb 24, 2016

AbelHu commented Feb 24, 2016

landesherr commented Feb 24, 2016

svrc commented Mar 14, 2016

AbelHu commented Mar 21, 2016

AbelHu commented Mar 21, 2016