Bug 1273785
| Summary: | Capsule stops listening on 9090 after log rotate | ||||||
|---|---|---|---|---|---|---|---|
| Product: | Red Hat Satellite | Reporter: | Peter Vreman <peter.vreman> | ||||
| Component: | Foreman Proxy | Assignee: | Dmitri Dolguikh <ddolguik> | ||||
| Status: | CLOSED ERRATA | QA Contact: | jcallaha | ||||
| Severity: | urgent | Docs Contact: | |||||
| Priority: | urgent | ||||||
| Version: | 6.1.3 | CC: | bbuckingham, bkearney, cwelton, inecas, jcallaha, ktordeur, ohadlevy, pmoravec, sauchter, sreber, suprabhu, xdmoon | ||||
| Target Milestone: | Unspecified | Keywords: | PrioBumpGSS, Triaged | ||||
| Target Release: | Unused | ||||||
| Hardware: | Unspecified | ||||||
| OS: | Unspecified | ||||||
| URL: | http://projects.theforeman.org/issues/12295 | ||||||
| Whiteboard: | |||||||
| Fixed In Version: | Doc Type: | Bug Fix | |||||
| Doc Text: | Story Points: | --- | |||||
| Clone Of: | |||||||
| : | 1315266 (view as bug list) | Environment: | |||||
| Last Closed: | 2016-09-27 09:01:32 UTC | Type: | Bug | ||||
| Regression: | --- | Mount Type: | --- | ||||
| Documentation: | --- | CRM: | |||||
| Verified Versions: | Category: | --- | |||||
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |||||
| Cloudforms Team: | --- | Target Upstream Version: | |||||
| Embargoed: | |||||||
| Bug Depends On: | |||||||
| Bug Blocks: | 1122832, 1315266, 1338516 | ||||||
| Attachments: |
|
||||||
|
Description
Peter Vreman
2015-10-21 08:40:28 UTC
This behaviour has also been observed also on a fresh installed Satellite 6.1.3 that did not have any clients attached The complete log of the fresh smart-proxy is attach Created attachment 1085052 [details]
smart proxy log
Reproduction can be done with a for loop to call condrestart multiple times.
[crash] root@li-lc-1578:/var/log/foreman-proxy# for (( i = 0 ; i < 10 ; i++ )); do
> service foreman-proxy condrestart
> lsof -P -n | grep 'foreman-proxy.*TCP'
> done
Stopping foreman-proxy: [ OK ]
Starting foreman-proxy: [ OK ]
ruby 11826 foreman-proxy 5u IPv4 4010715 0t0 TCP *:8000 (LISTEN)
Stopping foreman-proxy: [ OK ]
Starting foreman-proxy: [ OK ]
ruby 11865 foreman-proxy 5u IPv4 4011534 0t0 TCP *:9090 (LISTEN)
ruby 11865 foreman-proxy 6u IPv4 4011536 0t0 TCP *:8000 (LISTEN)
Stopping foreman-proxy: [ OK ]
Starting foreman-proxy: [ OK ]
ruby 11900 foreman-proxy 5u IPv4 4011756 0t0 TCP *:9090 (LISTEN)
Stopping foreman-proxy: [ OK ]
Starting foreman-proxy: [ OK ]
ruby 11938 foreman-proxy 5u IPv4 4011945 0t0 TCP *:9090 (LISTEN)
Stopping foreman-proxy: [ OK ]
Starting foreman-proxy: [ OK ]
ruby 11975 foreman-proxy 5u IPv4 4012182 0t0 TCP *:8000 (LISTEN)
Stopping foreman-proxy: [ OK ]
Starting foreman-proxy: [ OK ]
ruby 12013 foreman-proxy 5u IPv4 4012426 0t0 TCP *:9090 (LISTEN)
Stopping foreman-proxy: [ OK ]
Starting foreman-proxy: [ OK ]
ruby 12048 foreman-proxy 5u IPv4 4012605 0t0 TCP *:8000 (LISTEN)
ruby 12048 foreman-proxy 6u IPv4 4012608 0t0 TCP *:9090 (LISTEN)
Stopping foreman-proxy: [ OK ]
Starting foreman-proxy: [ OK ]
ruby 12090 foreman-proxy 5u IPv4 4012863 0t0 TCP *:9090 (LISTEN)
Stopping foreman-proxy: [ OK ]
Starting foreman-proxy: [ OK ]
ruby 12125 foreman-proxy 5u IPv4 4013045 0t0 TCP *:9090 (LISTEN)
Stopping foreman-proxy: [ OK ]
Starting foreman-proxy: [ OK ]
ruby 12159 foreman-proxy 5u IPv4 4013285 0t0 TCP *:8000 (LISTEN)
ruby 12159 foreman-proxy 6u IPv4 4013295 0t0 TCP *:9090 (LISTEN)
[crash] root@li-lc-1578:/var/log/foreman-proxy#
Also not the strange port 8000 that is sometimes LISTEN on instead or additional to 9090
Created redmine issue http://projects.theforeman.org/issues/12295 from this bug The goal is resolve this as part of an upcoming 6.1.z. After hitting the issue again I did a manual service restart and noticed the remark that it was not running before, but the process was still there. So it looks like the service stop is not working correctly and keeping the ports still open. vrempet@li-lc-1017 ~ $ date Thu Jan 7 13:18:33 GMT 2016 vrempet@li-lc-1017 ~ $ ps aux | grep proxy 493 21251 0.2 0.1 162908 54052 ? SNl 03:43 1:30 ruby /usr/share/foreman-proxy/bin/smart-proxy vrempet 27005 0.0 0.0 103308 852 pts/0 S+ 13:18 0:00 grep proxy vrempet@li-lc-1017 ~ $ sudo lsof -P -p 21251 | grep IP ruby 21251 foreman-proxy 5u IPv4 47708181 0t0 TCP *:8000 (LISTEN) vrempet@li-lc-1017 ~ $ sudo service foreman-proxy restart Stopping foreman-proxy: foreman-proxy was not running. [FAILED] Starting foreman-proxy: [ OK ] vrempet@li-lc-1017 ~ $ ps aux | grep proxy 493 21251 0.2 0.1 162908 54052 ? SNl 03:43 1:31 ruby /usr/share/foreman-proxy/bin/smart-proxy 493 28531 0.4 0.1 162916 54796 ? Sl 13:22 0:00 ruby /usr/share/foreman-proxy/bin/smart-proxy vrempet 28582 0.0 0.0 103308 852 pts/0 S+ 13:23 0:00 grep proxy vrempet@li-lc-1017 ~ $ sudo lsof -P -p 21251 | grep IP ruby 21251 foreman-proxy 5u IPv4 47708181 0t0 TCP *:8000 (LISTEN) vrempet@li-lc-1017 ~ $ sudo lsof -P -p 28531 | grep IP ruby 28531 foreman-proxy 5u IPv4 48735423 0t0 TCP *:9090 (LISTEN) Below is the gdb output of process 21252: (gdb) thread 2 [Switching to thread 2 (Thread 0x7f8fc9fcd700 (LWP 21252))]#0 0x000000367ee0ba0e in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 (gdb) bt #0 0x000000367ee0ba0e in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #1 0x000000367f63303c in ?? () from /usr/lib64/libruby.so.1.8 #2 0x000000367ee07a51 in start_thread () from /lib64/libpthread.so.0 #3 0x000000367eae893d in clone () from /lib64/libc.so.6 (gdb) thr 1 [Switching to thread 1 (Thread 0x7f8fce79c700 (LWP 21251))]#0 0x000000367eae13b3 in select () from /lib64/libc.so.6 (gdb) bt #0 0x000000367eae13b3 in select () from /lib64/libc.so.6 #1 0x000000367f63fb63 in rb_thread_schedule () from /usr/lib64/libruby.so.1.8 #2 0x000000367f641dd9 in rb_thread_select () from /usr/lib64/libruby.so.1.8 #3 0x000000367f65c2a4 in ?? () from /usr/lib64/libruby.so.1.8 #4 0x000000367f63c765 in ?? () from /usr/lib64/libruby.so.1.8 #5 0x000000367f63cb87 in ?? () from /usr/lib64/libruby.so.1.8 #6 0x000000367f6396d2 in ?? () from /usr/lib64/libruby.so.1.8 #7 0x000000367f6372c4 in ?? () from /usr/lib64/libruby.so.1.8 #8 0x000000367f638527 in ?? () from /usr/lib64/libruby.so.1.8 #9 0x000000367f639b40 in ?? () from /usr/lib64/libruby.so.1.8 #10 0x000000367f637ccc in ?? () from /usr/lib64/libruby.so.1.8 #11 0x000000367f63aeda in ?? () from /usr/lib64/libruby.so.1.8 #12 0x000000367f636d5a in ?? () from /usr/lib64/libruby.so.1.8 #13 0x000000367f63c683 in ?? () from /usr/lib64/libruby.so.1.8 #14 0x000000367f63cb87 in ?? () from /usr/lib64/libruby.so.1.8 #15 0x000000367f6396d2 in ?? () from /usr/lib64/libruby.so.1.8 #16 0x000000367f63a01f in ?? () from /usr/lib64/libruby.so.1.8 #17 0x000000367f63c683 in ?? () from /usr/lib64/libruby.so.1.8 #18 0x000000367f63cb87 in ?? () from /usr/lib64/libruby.so.1.8 #19 0x000000367f6396d2 in ?? () from /usr/lib64/libruby.so.1.8 #20 0x000000367f63c683 in ?? () from /usr/lib64/libruby.so.1.8 #21 0x000000367f63cb87 in ?? () from /usr/lib64/libruby.so.1.8 #22 0x000000367f6396d2 in ?? () from /usr/lib64/libruby.so.1.8 #23 0x000000367f64765c in ?? () from /usr/lib64/libruby.so.1.8 #24 0x000000367f63862a in ?? () from /usr/lib64/libruby.so.1.8 #25 0x000000367f63c683 in ?? () from /usr/lib64/libruby.so.1.8 #26 0x000000367f63cb87 in ?? () from /usr/lib64/libruby.so.1.8 #27 0x000000367f6396d2 in ?? () from /usr/lib64/libruby.so.1.8 #28 0x000000367f63aeda in ?? () from /usr/lib64/libruby.so.1.8 #29 0x000000367f643304 in ?? () from /usr/lib64/libruby.so.1.8 #30 0x000000367f63c765 in ?? () from /usr/lib64/libruby.so.1.8 #31 0x000000367f63cb87 in ?? () from /usr/lib64/libruby.so.1.8 #32 0x000000367f63d438 in rb_funcall2 () from /usr/lib64/libruby.so.1.8 #33 0x000000367f63d4d2 in rb_obj_call_init () from /usr/lib64/libruby.so.1.8 #34 0x000000367f63d53e in ?? () from /usr/lib64/libruby.so.1.8 #35 0x000000367f63c765 in ?? () from /usr/lib64/libruby.so.1.8 #36 0x000000367f63cb87 in ?? () from /usr/lib64/libruby.so.1.8 #37 0x000000367f6396d2 in ?? () from /usr/lib64/libruby.so.1.8 #38 0x000000367f63a01f in ?? () from /usr/lib64/libruby.so.1.8 #39 0x000000367f63725e in ?? () from /usr/lib64/libruby.so.1.8 #40 0x000000367f63c683 in ?? () from /usr/lib64/libruby.so.1.8 #41 0x000000367f63cb87 in ?? () from /usr/lib64/libruby.so.1.8 #42 0x000000367f6396d2 in ?? () from /usr/lib64/libruby.so.1.8 #43 0x000000367f649b3b in ?? () from /usr/lib64/libruby.so.1.8 #44 0x000000367f649b85 in ruby_exec () from /usr/lib64/libruby.so.1.8 I could reproduce the issue with using strace
1. Login a foreman-proxy: sudo -u foreman-proxy -i
2. Disable daemon in /etc/foreman-proxy/settings.yml
3. Start foreman proxy under strace
strace -s 160000 -t -f /usr/share/foreman-proxy/bin/smart-proxy 2> /tmp/smart-proxy.trace
4. In second terminal:
grep bind/tmp/smart-proxy.trace
lsof -P -n | grep 'foreman-proxy.*TCP'
Adding a 'sleep 5' between the thread starts in lib/smart_proxy.rb (or lib/launcher.rb in foreman 1.10) seems to 'solve' the issue:
t1 = Thread.new { https_app.start } unless https_app.nil?
+ sleep 5
t2 = Thread.new { http_app.start } unless http_app.nil?
Below are the test results, before the patch and after the patch: Before the patch: [crash] root@li-lc-1578:~# for (( i = 0 ; i < 10 ; i++ )); do service foreman-proxy restart; sleep 7; lsof -P -n | grep 'foreman-proxy.*TCP'; done Stopping foreman-proxy: [ OK ] Starting foreman-proxy: [ OK ] ruby 29827 foreman-proxy 5u IPv4 37122432 0t0 TCP *:9090 (LISTEN) Stopping foreman-proxy: [ OK ] Starting foreman-proxy: [ OK ] ruby 29870 foreman-proxy 5u IPv4 37122918 0t0 TCP *:9090 (LISTEN) Stopping foreman-proxy: [ OK ] Starting foreman-proxy: [ OK ] ruby 29908 foreman-proxy 5u IPv4 37123469 0t0 TCP *:8000 (LISTEN) ruby 29908 foreman-proxy 6u IPv4 37123474 0t0 TCP *:9090 (LISTEN) Stopping foreman-proxy: [ OK ] Starting foreman-proxy: [ OK ] ruby 29980 foreman-proxy 5u IPv4 37123839 0t0 TCP *:9090 (LISTEN) ruby 29980 foreman-proxy 6u IPv4 37123845 0t0 TCP *:8000 (LISTEN) Stopping foreman-proxy: [ OK ] Starting foreman-proxy: [ OK ] ruby 30019 foreman-proxy 5u IPv4 37124153 0t0 TCP *:8000 (LISTEN) ruby 30019 foreman-proxy 6u IPv4 37124157 0t0 TCP *:9090 (LISTEN) Stopping foreman-proxy: [ OK ] Starting foreman-proxy: [ OK ] ruby 30109 foreman-proxy 5u IPv4 37124507 0t0 TCP *:9090 (LISTEN) ruby 30109 foreman-proxy 6u IPv4 37124515 0t0 TCP *:8000 (LISTEN) Stopping foreman-proxy: [ OK ] Starting foreman-proxy: [ OK ] ruby 30147 foreman-proxy 5u IPv4 37124769 0t0 TCP *:9090 (LISTEN) Stopping foreman-proxy: [ OK ] Starting foreman-proxy: [ OK ] ruby 30186 foreman-proxy 5u IPv4 37125057 0t0 TCP *:9090 (LISTEN) Stopping foreman-proxy: [ OK ] Starting foreman-proxy: [ OK ] ruby 30223 foreman-proxy 5u IPv4 37125344 0t0 TCP *:9090 (LISTEN) Stopping foreman-proxy: [ OK ] Starting foreman-proxy: [ OK ] ruby 30259 foreman-proxy 5u IPv4 37125597 0t0 TCP *:9090 (LISTEN) Apply the patch: [crash] root@li-lc-1578:~# mcedit /usr/share/foreman-proxy/lib/smart_proxy.rb After the patch: [crash] root@li-lc-1578:~# for (( i = 0 ; i < 10 ; i++ )); do service foreman-proxy restart; sleep 7; lsof -P -n | grep 'foreman-proxy.*TCP'; done Stopping foreman-proxy: [ OK ] Starting foreman-proxy: [ OK ] ruby 30726 foreman-proxy 5u IPv4 37129091 0t0 TCP *:9090 (LISTEN) ruby 30726 foreman-proxy 6u IPv4 37129159 0t0 TCP *:8000 (LISTEN) Stopping foreman-proxy: [ OK ] Starting foreman-proxy: [ OK ] ruby 30762 foreman-proxy 5u IPv4 37129519 0t0 TCP *:9090 (LISTEN) ruby 30762 foreman-proxy 6u IPv4 37129585 0t0 TCP *:8000 (LISTEN) Stopping foreman-proxy: [ OK ] Starting foreman-proxy: [ OK ] ruby 30801 foreman-proxy 5u IPv4 37129874 0t0 TCP *:9090 (LISTEN) ruby 30801 foreman-proxy 6u IPv4 37129936 0t0 TCP *:8000 (LISTEN) Stopping foreman-proxy: [ OK ] Starting foreman-proxy: [ OK ] ruby 30838 foreman-proxy 5u IPv4 37130124 0t0 TCP *:9090 (LISTEN) ruby 30838 foreman-proxy 6u IPv4 37130200 0t0 TCP *:8000 (LISTEN) Stopping foreman-proxy: [ OK ] Starting foreman-proxy: [ OK ] ruby 30875 foreman-proxy 5u IPv4 37130382 0t0 TCP *:9090 (LISTEN) ruby 30875 foreman-proxy 6u IPv4 37130452 0t0 TCP *:8000 (LISTEN) Stopping foreman-proxy: [ OK ] Starting foreman-proxy: [ OK ] ruby 30962 foreman-proxy 5u IPv4 37130716 0t0 TCP *:9090 (LISTEN) ruby 30962 foreman-proxy 6u IPv4 37130779 0t0 TCP *:8000 (LISTEN) Stopping foreman-proxy: [ OK ] Starting foreman-proxy: [ OK ] ruby 31001 foreman-proxy 5u IPv4 37131033 0t0 TCP *:9090 (LISTEN) ruby 31001 foreman-proxy 6u IPv4 37131094 0t0 TCP *:8000 (LISTEN) Stopping foreman-proxy: [ OK ] Starting foreman-proxy: [ OK ] ruby 31039 foreman-proxy 5u IPv4 37131276 0t0 TCP *:9090 (LISTEN) ruby 31039 foreman-proxy 6u IPv4 37131384 0t0 TCP *:8000 (LISTEN) Stopping foreman-proxy: [ OK ] Starting foreman-proxy: [ OK ] ruby 31077 foreman-proxy 5u IPv4 37131562 0t0 TCP *:9090 (LISTEN) ruby 31077 foreman-proxy 6u IPv4 37131638 0t0 TCP *:8000 (LISTEN) Stopping foreman-proxy: [ OK ] Starting foreman-proxy: [ OK ] ruby 31116 foreman-proxy 5u IPv4 37131875 0t0 TCP *:9090 (LISTEN) ruby 31116 foreman-proxy 6u IPv4 37131934 0t0 TCP *:8000 (LISTEN) Moving this out of 6.1.7 due to capacity issues. Will keep it on the 6.1.z and 6.2 trackers to ensure that it is evaluated for both. Upstream bug assigned to ddolguik Upstream bug assigned to ddolguik Moving to POST since upstream bug http://projects.theforeman.org/issues/12295 has been closed ------------- Anonymous Applied in changeset commit:7cc71a107f37f1c7dfc12f2791906565e796bed6. Verified in Satellite 6.1.10. No issues seen with logrotate or proxy restart. [root@rhsm-qe-1 ~]# for (( i = 0 ; i < 10 ; i++ )); do service foreman-proxy restart; sleep 7; lsof -P -n | grep 'foreman-proxy.*TCP'; done Redirecting to /bin/systemctl restart foreman-proxy.service ruby 31806 foreman-proxy 9u IPv4 3711894 0t0 TCP *:8000 (LISTEN) ruby 31806 foreman-proxy 10u IPv4 3705613 0t0 TCP *:9090 (LISTEN) Redirecting to /bin/systemctl restart foreman-proxy.service ruby 31847 foreman-proxy 9u IPv4 3691476 0t0 TCP *:8000 (LISTEN) ruby 31847 foreman-proxy 10u IPv4 3711962 0t0 TCP *:9090 (LISTEN) Redirecting to /bin/systemctl restart foreman-proxy.service ruby 31886 foreman-proxy 9u IPv4 3994157 0t0 TCP *:9090 (LISTEN) ruby 31886 foreman-proxy 10u IPv4 3715225 0t0 TCP *:8000 (LISTEN) Redirecting to /bin/systemctl restart foreman-proxy.service ruby 31927 foreman-proxy 9u IPv4 3711984 0t0 TCP *:8000 (LISTEN) ruby 31927 foreman-proxy 10u IPv4 4005927 0t0 TCP *:9090 (LISTEN) Redirecting to /bin/systemctl restart foreman-proxy.service ruby 31966 foreman-proxy 9u IPv4 3711991 0t0 TCP *:8000 (LISTEN) ruby 31966 foreman-proxy 10u IPv4 3994173 0t0 TCP *:9090 (LISTEN) Redirecting to /bin/systemctl restart foreman-proxy.service ruby 32006 foreman-proxy 9u IPv4 4007938 0t0 TCP *:8000 (LISTEN) ruby 32006 foreman-proxy 10u IPv4 3994188 0t0 TCP *:9090 (LISTEN) Redirecting to /bin/systemctl restart foreman-proxy.service ruby 32046 foreman-proxy 9u IPv4 4007952 0t0 TCP *:8000 (LISTEN) ruby 32046 foreman-proxy 10u IPv4 3997922 0t0 TCP *:9090 (LISTEN) Redirecting to /bin/systemctl restart foreman-proxy.service ruby 32086 foreman-proxy 9u IPv4 3705856 0t0 TCP *:8000 (LISTEN) ruby 32086 foreman-proxy 10u IPv4 3998004 0t0 TCP *:9090 (LISTEN) Redirecting to /bin/systemctl restart foreman-proxy.service ruby 32128 foreman-proxy 9u IPv4 4008330 0t0 TCP *:8000 (LISTEN) ruby 32128 foreman-proxy 10u IPv4 3998257 0t0 TCP *:9090 (LISTEN) Redirecting to /bin/systemctl restart foreman-proxy.service ruby 32167 foreman-proxy 9u IPv4 4008338 0t0 TCP *:8000 (LISTEN) ruby 32167 foreman-proxy 10u IPv4 3998331 0t0 TCP *:9090 (LISTEN) Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHBA-2016:1938 |