client cannot connect to thrift server using huptime --exec in supervisor

[tallmad]

The client connection hanged util time was out.
The thrift server uses python gevent

[amscanne]

Did it work with --fork?

I'd be happy to take a look, if possible can you attach the output from a run with huptime --debug --exec ?

[tallmad]

run with huptime --debug --exec
log output when setup thrift server:

25678 huptime 32214: Initializing...
25679 huptime 32214: Exit strategy is exec.
25680 huptime 32214: -wait- 1266
25681 huptime 32214: -acquired- 1266
25682 huptime 32214: -release- 1268
25683 huptime 32214: Saving all initial file descriptors.
25684 huptime 32214: Saved fd 0 (offset -1).
25685 huptime 32214: Saved fd 1 (offset -1).
25686 huptime 32214: Saved fd 2 (offset -1).
25687 huptime 32214: do_close(6, ...) ...
25688 huptime 32214: -wait- 406
25689 huptime 32214: -acquired- 406
25690 huptime 32214: -release- 410
25691 huptime 32214: do_close(6) => 0 (no info)
25692 huptime 32214: Saved environment.
25693 huptime 32214: do_close(6, ...) ...
25694 huptime 32214: -wait- 406
25695 huptime 32214: -acquired- 406
25696 huptime 32214: -release- 410
25697 huptime 32214: do_close(6) => 0 (no info)
25698 huptime 32214: Saved args.
25699 huptime 32214:  arg0=/srv/virtualenvs/zeus2env/bin/python
25700 huptime 32214:  arg1=/srv/virtualenvs/zeus2env/bin/zserve
25701 huptime 32214:  arg2=oas
25702 huptime 32214: Saved cwd.
25703 huptime 32214: Saved exe.
25704 huptime 32214: Installed signal handlers.
25705 huptime 32214: Initialization complete.
25706 huptime 32215: Initializing...
25707 huptime 32215: Exit strategy is exec.
25708 huptime 32215: -wait- 1266
25709 huptime 32215: -acquired- 1266
25710 huptime 32215: -release- 1268
25711 huptime 32215: Saving all initial file descriptors.
25712 huptime 32215: Saved fd 0 (offset -1).
25713 huptime 32215: Saved fd 1 (offset -1).
25714 huptime 32215: Saved fd 2 (offset -1).
25715 huptime 32215: Saved fd 3 (offset -1).
25716 huptime 32215: Saved fd 4 (offset -1).
25717 huptime 32215: Saved fd 5 (offset -1).
25718 huptime 32215: Saved fd 6 (offset 0).
25719 huptime 32215: Saved fd 7 (offset 0).
25720 huptime 32215: Saved fd 8 (offset 0).
25721 huptime 32215: Saved fd 9 (offset 0).
25722 huptime 32215: Saved fd 10 (offset 0).                                                                                                                                                                                                  
25723 huptime 32215: Saved fd 11 (offset 0).
25724 huptime 32215: do_close(24, ...) ...
25725 huptime 32215: -wait- 406
25726 huptime 32215: -acquired- 406
25727 huptime 32215: -release- 410
25728 huptime 32215: do_close(24) => 0 (no info)
25729 huptime 32215: Saved environment.
25730 huptime 32215: do_close(24, ...) ...
25731 huptime 32215: -wait- 406
25732 huptime 32215: -acquired- 406
25733 huptime 32215: -release- 410
25734 huptime 32215: do_close(24) => 0 (no info)                                                                                                                                                                                              
25735 huptime 32215: Saved args.
25736 huptime 32215:  arg0=sh
25737 huptime 32215:  arg1=-c
25738 huptime 32215:  arg2=uname -p 2> /dev/null
25739 huptime 32215: Saved cwd.
25740 huptime 32215: Saved exe.
25741 huptime 32215: Installed signal handlers.
25742 huptime 32215: Initialization complete.
25743 huptime 32215: do_close(2, ...) ...
25744 huptime 32215: -wait- 406
25745 huptime 32215: -acquired- 406
25746 huptime 32215: -release- 410
25747 huptime 32215: -release- 388
25748 huptime 32215: do_dup3(25, 2, ...) => 2
25749 huptime 32215: do_close(25, ...) ...
25750 huptime 32215: -wait- 406
25751 huptime 32215: -acquired- 406
25752 huptime 32215: -release- 410
25753 huptime 32215: do_close(25) => 0 (no info)
25754 huptime 32214: do_close(13, ...) ...
25755 huptime 32214: -wait- 406
25756 huptime 32214: -acquired- 406
25757 huptime 32214: -release- 410
25758 huptime 32214: do_close(13) => 0 (no info)
25759 huptime 32217: Initializing...
25760 huptime 32217: Exit strategy is exec.
25761 huptime 32217: -wait- 1266
25762 huptime 32217: -acquired- 1266
25763 huptime 32217: -release- 1268
25764 huptime 32217: Saving all initial file descriptors.
25765 huptime 32217: Saved fd 0 (offset -1).
25766 huptime 32217: Saved fd 1 (offset -1).
25767 huptime 32217: Saved fd 2 (offset -1).
25768 huptime 32217: Saved fd 3 (offset -1).
25769 huptime 32217: Saved fd 4 (offset -1).
25770 huptime 32217: Saved fd 5 (offset -1).
25771 huptime 32217: Saved fd 6 (offset 0).
25772 huptime 32217: Saved fd 7 (offset 0).
25773 huptime 32217: Saved fd 8 (offset 0).
25774 huptime 32217: Saved fd 9 (offset 0).
25775 huptime 32217: Saved fd 10 (offset 0).
25776 huptime 32217: Saved fd 11 (offset 0).
25777 huptime 32217: Saved fd 12 (offset 0).
25778 huptime 32217: do_close(26, ...) ...
25779 huptime 32217: -wait- 406
25780 huptime 32217: -acquired- 406
25781 huptime 32217: -release- 410
25782 huptime 32217: do_close(26) => 0 (no info)
25783 huptime 32217: Saved environment.
25784 huptime 32217: do_close(26, ...) ...
25785 huptime 32217: -wait- 406
25786 huptime 32217: -acquired- 406
25787 huptime 32217: -release- 410
25788 huptime 32217: do_close(26) => 0 (no info)
25789 huptime 32217: Saved args.
25790 huptime 32217:  arg0=sh
25791 huptime 32217:  arg1=-c
25792 huptime 32217:  arg2=/sbin/ldconfig -p 2>/dev/null
25793 huptime 32217: Saved cwd.
25794 huptime 32217: Saved exe.
25795 huptime 32217: Installed signal handlers.
25796 huptime 32217: Initialization complete.
25797 huptime 32217: do_close(2, ...) ...
25798 huptime 32217: -wait- 406
25799 huptime 32217: -acquired- 406
25800 huptime 32217: -release- 410
25801 huptime 32217: -release- 388
25802 huptime 32217: do_dup3(27, 2, ...) => 2
25803 huptime 32217: do_close(27, ...) ...
25804 huptime 32217: -wait- 406
25805 huptime 32217: -acquired- 406
25806 huptime 32217: -release- 410
25807 huptime 32217: do_close(27) => 0 (no info)
25808 huptime 32219: Initializing...
25809 huptime 32219: Exit strategy is exec.
25810 huptime 32219: -wait- 1266
25811 huptime 32219: -acquired- 1266
25812 huptime 32219: -release- 1268
25813 huptime 32219: Saving all initial file descriptors.
25814 huptime 32219: Saved fd 0 (offset -1).
25815 huptime 32219: Saved fd 1 (offset -1).
25816 huptime 32219: Saved fd 2 (offset -1).
25817 huptime 32219: Saved fd 3 (offset -1).
25818 huptime 32219: Saved fd 4 (offset -1).
25819 huptime 32219: Saved fd 5 (offset -1).
25820 huptime 32219: Saved fd 6 (offset 0).
25821 huptime 32219: Saved fd 7 (offset 0).
25822 huptime 32219: Saved fd 8 (offset 0).                                                                                                                                                                                                   
25823 huptime 32219: Saved fd 9 (offset 0).
25824 huptime 32219: Saved fd 10 (offset 0).
25825 huptime 32219: Saved fd 11 (offset 0).
25826 huptime 32219: Saved fd 12 (offset 0).
25827 huptime 32219: do_close(26, ...) ...
25828 huptime 32219: -wait- 406
25829 huptime 32219: -acquired- 406
25830 huptime 32219: -release- 410
25831 huptime 32219: do_close(26) => 0 (no info)
25832 huptime 32219: Saved environment.
25833 huptime 32219: do_close(26, ...) ...
25834 huptime 32219: -wait- 406
25835 huptime 32219: -acquired- 406
25836 huptime 32219: -release- 410
25837 huptime 32219: do_close(26) => 0 (no info)
25838 huptime 32219: Saved args.
25839 huptime 32219:  arg0=sh
25840 huptime 32219:  arg1=-c
25841 huptime 32219:  arg2=/sbin/ldconfig -p 2>/dev/null
25842 huptime 32219: Saved cwd.
25843 huptime 32219: Saved exe.
25844 huptime 32219: Installed signal handlers.
25845 huptime 32219: Initialization complete.
25846 huptime 32219: do_close(2, ...) ...
25847 huptime 32219: -wait- 406
25848 huptime 32219: -acquired- 406
25849 huptime 32219: -release- 410
25850 huptime 32219: -release- 388
25851 huptime 32219: do_dup3(27, 2, ...) => 2
25852 huptime 32219: do_close(27, ...) ...
25853 huptime 32219: -wait- 406
25854 huptime 32219: -acquired- 406
25855 huptime 32219: -release- 410
25856 huptime 32219: do_close(27) => 0 (no info)
25857 huptime 32214: do_close(17, ...) ...
25858 huptime 32214: -wait- 406
25859 huptime 32214: -acquired- 406
25860 huptime 32214: -release- 410
25861 huptime 32214: do_close(17) => 0 (no info)
25862 huptime 32214: do_close(15, ...) ...
25863 huptime 32214: -wait- 406
25864 huptime 32214: -acquired- 406
25865 huptime 32214: -release- 410
25866 huptime 32214: do_close(15) => 0 (no info)
25867 huptime 32214: do_close(15, ...) ...
25868 huptime 32214: -wait- 406
25869 huptime 32214: -acquired- 406
25870 huptime 32214: -release- 410
25871 huptime 32214: do_close(15) => 0 (no info)
25872 2013-12-24 10:48:22,517 INFO   [zeus.oas.server][32214] making oas server at 0.0.0.0:19080 ...
25873 2013-12-24 10:48:22,517 INFO   [zeus.oas.server][32214] pool size: 1
25874 2013-12-24 10:48:22,517 INFO   [zeus.oas.server][32214] timeout: 30
25875 2013-12-24 10:48:22,517 INFO   [zeus.oas.dispatcher][32214] oas server starting..
25876 2013-12-24 10:48:22,518 INFO   [zeus.oas.dispatcher][32214] __init__() response time 0.262975692749ms
25877 huptime 32214: do_bind(8, ...) ...
25878 huptime 32214: -wait- 957
25879 huptime 32214: -acquired- 957
25880 huptime 32214: -release- 1050
25881 huptime 32214: do_bind(8, ...) => 0
25882 huptime 32214: do_listen(8, ...) ...
25883 huptime 32214: -wait- 1062
25884 huptime 32214: -acquired- 1062
25885 huptime 32214: -release- 1109
25886 huptime 32214: do_listen(8, 128) => 0
25887 huptime 32214: do_fork() ...
25888 huptime 32214: -wait- 922
25889 huptime 32214: -acquired- 922
25890 huptime 32214: -release- 943
25891 huptime 32214: do_fork() => 32225

[tallmad]

when a client try to connect the server
the output(I tried twice):

25892 huptime 32225: do_fork() => 0
25893 huptime 32225: do_close(9, ...) ...
25894 huptime 32225: -wait- 406
25895 huptime 32225: -acquired- 406
25896 huptime 32225: -release- 410
25897 huptime 32225: do_close(9) => 0 (no info)
25898 huptime 32225: do_accept4(8, ...) ...
25899 huptime 32225: -wait- 1121
25900 huptime 32225: -acquired- 1121
25901 huptime 32225: -release- 1156
25902 huptime 32225: -wait- 1168
25903 huptime 32225: -acquired- 1168
25904 huptime 32225: -release- 1208
25905 huptime 32225: do_accept4(8, ...) => 11 (tracked 1)
25906 huptime 32225: do_accept4(8, ...) ...
25907 huptime 32225: -wait- 1121
25908 huptime 32225: -acquired- 1121
25909 huptime 32225: -release- 1156
25910 huptime 32225: -wait- 1168
25911 huptime 32225: -acquired- 1168
25912 huptime 32225: -release- 1208
25913 huptime 32225: do_accept4(8, ...) => 12 (tracked 2)
25914 huptime 32225: do_accept4(8, ...) ...
25915 huptime 32225: -wait- 1121
25916 huptime 32225: -acquired- 1121
25917 huptime 32225: -release- 1156

[tallmad]

It doesn't work with --fork, either

[amscanne]

Okay, I may be missing something here. I'm not sure where the pids 32215, 32216, 32217 are coming from (as we should see do_fork() messages.

In any case, I'll look into the problem -- thanks for the information. Thrift may work by co-ordinating with workers over pipes, and saving the initial set of FDs might meet it's expectations.