Bug 1548098
Summary: | After logrotate the smart_proxy_dynflow_core service points to the deleted/orphan log file which results into current log being empty and hence not rotating log further | ||
---|---|---|---|
Product: | Red Hat Satellite | Reporter: | Gauravi <gapatil> |
Component: | Remote Execution | Assignee: | satellite6-bugs <satellite6-bugs> |
Status: | CLOSED ERRATA | QA Contact: | Nikhil Kathole <nkathole> |
Severity: | high | Docs Contact: | |
Priority: | urgent | ||
Version: | 6.2.13 | CC: | ahumbe, aruzicka, ddolguik, inecas, jcallaha, pcreech, sghai |
Target Milestone: | 6.4.0 | Keywords: | Reopened, Triaged |
Target Release: | Unused | ||
Hardware: | x86_64 | ||
OS: | Linux | ||
Whiteboard: | |||
Fixed In Version: | rubygem-smart_proxy_dynflow-0.2.1-1 | Doc Type: | If docs needed, set a value |
Doc Text: | Story Points: | --- | |
Clone Of: | Environment: | ||
Last Closed: | 2018-10-16 19:12:15 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: |
Description
Gauravi
2018-02-22 17:33:11 UTC
Connecting redmine issue http://projects.theforeman.org/issues/19224 from this bug This has been fixed in upstream and the fix has been delivered as part of the 6.3 release. The issue still persists on Satellite v 6.3 GA, so reopening bugzilla. Here are the details from the local reproducer: # ps -elf | grep smart_proxy 1 S foreman+ 7953 1 0 80 0 - 237608 poll_s Feb22 ? 00:00:37 ruby /usr/bin/smart_proxy_dynflow_core -d -p /var/run/foreman-proxy/smart_proxy_dynflow_core.pid 0 S root 24849 14111 0 80 0 - 28166 pipe_w 15:22 pts/0 00:00:00 grep --color=auto smart_proxy # lsof -p 7953 | grep smart_proxy ruby 7953 foreman-proxy 7w REG 253,0 141 1225171 /var/log/foreman-proxy/smart_proxy_dynflow_core.log # ll /var/log/foreman-proxy total 8 -rw-r--r--. 1 foreman-proxy foreman-proxy 0 Feb 22 19:30 cron.log -rw-r--r--. 1 foreman-proxy foreman-proxy 0 Feb 23 03:19 proxy.log -rw-r--r--. 1 foreman-proxy foreman-proxy 2625 Feb 22 19:05 proxy.log-20180223.gz -rw-r--r--. 1 foreman-proxy foreman-proxy 141 Feb 27 15:22 smart_proxy_dynflow_core.log # logrotate -f /etc/logrotate.conf # ll /var/log/foreman-proxy total 8 -rw-r--r--. 1 foreman-proxy foreman-proxy 0 Feb 22 19:30 cron.log -rw-r--r--. 1 foreman-proxy foreman-proxy 0 Feb 23 03:19 proxy.log -rw-r--r--. 1 foreman-proxy foreman-proxy 2625 Feb 22 19:05 proxy.log-20180223.gz -rw-r--r--. 1 foreman-proxy foreman-proxy 0 Feb 27 15:23 smart_proxy_dynflow_core.log -rw-r--r--. 1 foreman-proxy foreman-proxy 144 Feb 27 15:22 smart_proxy_dynflow_core.log-20180227.gz # lsof -p 7953 | grep smart_proxy ruby 7953 foreman-proxy 7w REG 253,0 141 1225171 /var/log/foreman-proxy/smart_proxy_dynflow_core.log-20180227 (deleted) Installed packages on Sat6.3: satellite-6.3.0-23.0.el7sat.noarch tfm-rubygem-smart_proxy_dynflow_core-0.1.10-1.fm1_15.el7sat.noarch Moving this bug to POST for triage into Satellite 6 since the upstream issue http://projects.theforeman.org/issues/19224 has been resolved. The verification step you used is not correct: the process is informed about the need for re-opening the file, but it happens at the first attempt to writing to the file, rather than automatically (due to thread-safe reasons). To finish the verification steps, one can simulate a request to the process like this: curl -k --key /etc/foreman-proxy/foreman_ssl_key.pem --cert /etc/foreman-proxy/foreman_ssl_cert.pem https://localhost:8008/console And then verify the lsof again. @Ashish - can you verify this and in case it works, put it back to closed/current release? Hi Ivan, I checked today on my local satellite and I see that the log files are not getting rotated properly for smart_proxy_dynflow_core because of the issue reported here. Below is the output from my local Satellite v 6.3.1: - The smart_proxy_dynflow_core service was last time restarted on 20 April and till 25 April there are no logs generated because the process is still referring to the incorrect log file and since 21 April there are no logs rotated. # ps -elf | grep smart_proxy 1 S foreman+ 22294 1 0 80 0 - 64330 poll_s Apr20 ? 00:00:40 ruby /usr/bin/smart_proxy_dynflow_core -d -p /var/run/foreman-proxy/smart_proxy_dynflow_core.pid # lsof -p 22294 | grep smart_proxy ruby 22294 foreman-proxy 7w REG 253,0 1041 1083571 /var/log/foreman-proxy/smart_proxy_dynflow_core.log-20180421 (deleted) # ll -h /var/log/foreman-proxy/smart_proxy_dynflow_core.log* -rw-r--r--. 1 foreman-proxy foreman-proxy 0 Apr 21 03:48 /var/log/foreman-proxy/smart_proxy_dynflow_core.log -rw-r--r--. 1 foreman-proxy foreman-proxy 144 Feb 27 15:22 /var/log/foreman-proxy/smart_proxy_dynflow_core.log-20180227.gz -rw-r--r--. 1 foreman-proxy foreman-proxy 476 Mar 21 20:34 /var/log/foreman-proxy/smart_proxy_dynflow_core.log-20180322.gz -rw-r--r--. 1 foreman-proxy foreman-proxy 336 Apr 12 20:06 /var/log/foreman-proxy/smart_proxy_dynflow_core.log-20180413.gz -rw-r--r--. 1 foreman-proxy foreman-proxy 390 Apr 16 18:44 /var/log/foreman-proxy/smart_proxy_dynflow_core.log-20180417.gz -rw-r--r--. 1 foreman-proxy foreman-proxy 335 Apr 20 19:46 /var/log/foreman-proxy/smart_proxy_dynflow_core.log-20180421.gz - As suggested I tried to run the command followed by the lsof command, there is no change. # curl -k --key /etc/foreman-proxy/foreman_ssl_key.pem --cert /etc/foreman-proxy/foreman_ssl_cert.pem https://localhost:8008/console <html> <head> <meta charset="utf-8"> <meta http-equiv="X-UA-Compatible" content="IE=edge"> <meta name="viewport" content="width=device-width, initial-scale=1"> <link rel="icon" href="https://localhost:8008/console/images/logo-square.png" type="image/x-icon"> <title>Dynflow Console</title> <link rel="stylesheet" type="text/css" href="https://localhost:8008/console/vendor/bootstrap/css/bootstrap.css"> <link rel="stylesheet" type="text/css" href="https://localhost:8008/console/stylesheets/application.css"> <script src="https://localhost:8008/console/vendor/jquery/jquery.js"></script> <script src="https://localhost:8008/console/vendor/bootstrap/js/bootstrap.js"></script> <script src="https://localhost:8008/console/javascripts/application.js"></script> </head> <body> <nav class="navbar navbar-inverse navbar-fixed-top"> <div class="container"> <div class="navbar-header"> <button type="button" class="navbar-toggle collapsed" data-toggle="collapse" data-target="#navbar" aria-expanded="false" aria-controls="navbar"> <span class="sr-only">Toggle navigation</span> <span class="icon-bar"></span> <span class="icon-bar"></span> <span class="icon-bar"></span> </button> <a class="navbar-brand" href="https://localhost:8008/console/"> <img src="https://localhost:8008/console/images/logo-square.png"/> Dynflow </a> </div> <div id="navbar" class="collapse navbar-collapse"> <ul class="nav navbar-nav"> <li><a href="https://localhost:8008/console/">Execution plans</a></li> <li><a href="https://localhost:8008/console/status">Status</a></li> </ul> <ul class="nav navbar-nav navbar-right"> </ul> </div> </div> </nav> <div class="container"> <div class="row"> <h1>Listing execution plans</h1> <form action="https://localhost:8008/console/" method="GET"> <p>state: <input type="checkbox" name="filters[state][]" value="pending" checked/>pending <input type="checkbox" name="filters[state][]" value="scheduled" checked/>scheduled <input type="checkbox" name="filters[state][]" value="planning" checked/>planning <input type="checkbox" name="filters[state][]" value="planned" checked/>planned <input type="checkbox" name="filters[state][]" value="running" checked/>running <input type="checkbox" name="filters[state][]" value="paused" checked/>paused <input type="checkbox" name="filters[state][]" value="stopped" />stopped</p> <input type="submit" value="Filter"/> </form> <table class="table"> <thead> <tr> <th>Id</th> <th><a href="https://localhost:8008/console/?order_by=label&desc=false"> Label</a></th> <th><a href="https://localhost:8008/console/?order_by=state&desc=false"> State</a></th> <th><a href="https://localhost:8008/console/?order_by=result&desc=false"> Result</a></th> <th><a href="https://localhost:8008/console/?order_by=started_at&desc=false"> ▼ Started at</a></th> <th></th> </tr> </thead> </table> <ul class="pagination"> <li><a href="https://localhost:8008/console/?page=0">« Prev</a></li> <li><a href="https://localhost:8008/console/?page=1">Next »</a></li> </ul> </div> </div> </body> </html> # lsof -p 22294 | grep smart_proxy ruby 22294 foreman-proxy 7w REG 253,0 1115 1083571 /var/log/foreman-proxy/smart_proxy_dynflow_core.log-20180421 (deleted) Verified in Satellite 6.4 Snap 8. After log rotate, the correct log file is being written to. -bash-4.2# ll /var/log/foreman-proxy/ | grep smart_proxy -rw-r--r--. 1 foreman-proxy foreman-proxy 21 Jun 21 15:56 smart_proxy_dynflow_core.log -rw-r--r--. 1 foreman-proxy foreman-proxy 113 Jun 18 10:21 smart_proxy_dynflow_core.log-20180619.gz -bash-4.2# logrotate /etc/logrotate.conf -f -bash-4.2# ll /var/log/foreman-proxy/ | grep smart_proxy -rw-r--r--. 1 foreman-proxy foreman-proxy 0 Jun 21 15:57 smart_proxy_dynflow_core.log -rw-r--r--. 1 foreman-proxy foreman-proxy 113 Jun 18 10:21 smart_proxy_dynflow_core.log-20180619.gz -rw-r--r--. 1 foreman-proxy foreman-proxy 39 Jun 21 15:56 smart_proxy_dynflow_core.log-20180621.gz -bash-4.2# wget --no-check-certificate https://localhost:8008/ --2018-06-21 16:18:26-- https://localhost:8008/ Resolving localhost (localhost)... ::1, 127.0.0.1 Connecting to localhost (localhost)|::1|:8008... failed: Connection refused. Connecting to localhost (localhost)|127.0.0.1|:8008... connected. WARNING: no certificate subject alternative name matches requested host name ‘localhost’. HTTP request sent, awaiting response... 403 Forbidden 2018-06-21 16:18:27 ERROR 403: Forbidden. -bash-4.2# ll /var/log/foreman-proxy/ | grep smart_proxy -rw-r--r--. 1 foreman-proxy foreman-proxy 142 Jun 21 16:18 smart_proxy_dynflow_core.log -rw-r--r--. 1 foreman-proxy foreman-proxy 113 Jun 18 10:21 smart_proxy_dynflow_core.log-20180619.gz -rw-r--r--. 1 foreman-proxy foreman-proxy 39 Jun 21 15:56 smart_proxy_dynflow_core.log-20180621.gz -bash-4.2# curl -k --key /etc/foreman-proxy/foreman_ssl_key.pem --cert /etc/foreman-proxy/foreman_ssl_cert.pem https://localhost:8008/console <html> ... <snipped> ... </html> -bash-4.2# ll /var/log/foreman-proxy/ | grep smart_proxy -rw-r--r--. 1 foreman-proxy foreman-proxy 216 Jun 21 16:19 smart_proxy_dynflow_core.log -rw-r--r--. 1 foreman-proxy foreman-proxy 113 Jun 18 10:21 smart_proxy_dynflow_core.log-20180619.gz -rw-r--r--. 1 foreman-proxy foreman-proxy 39 Jun 21 15:56 smart_proxy_dynflow_core.log-20180621.gz snap 23, not 63 VERIFIED Version tested: Satellite 6.4 snap 23 # ll /var/log/foreman-proxy/ | grep smart_proxy -rw-r--r--. 1 foreman-proxy foreman-proxy 0 Sep 25 03:36 smart_proxy_dynflow_core.log -rw-r--r--. 1 foreman-proxy foreman-proxy 325 Sep 22 13:11 smart_proxy_dynflow_core.log-20180923.gz -rw-r--r--. 1 foreman-proxy foreman-proxy 260 Sep 24 03:16 smart_proxy_dynflow_core.log-20180924.gz # ps -elf | grep smart_proxy 1 S foreman+ 68199 1 0 80 0 - 1165214 poll_s 03:36 ? 00:00:00 ruby /usr/bin/smart_proxy_dynflow_core -d -p /var/run/foreman-proxy/smart_proxy_dynflow_core.pid 0 S root 69009 57650 0 80 0 - 28176 pipe_w 03:42 pts/0 00:00:00 grep --color=auto smart_proxy # lsof -p 68199 | grep smart_proxy ruby 68199 foreman-proxy 9w REG 253,0 0 637670876 /var/log/foreman-proxy/smart_proxy_dynflow_core.log Tested scenarios: 1. WHEN Log file is empty, logrorate wont make changes. # tail /var/log/foreman-proxy/smart_proxy_dynflow_core.log # logrotate /etc/logrotate.conf -f # lsof -p 68199 | grep smart_proxy ruby 68199 foreman-proxy 9w REG 253,0 0 637670876 /var/log/foreman-proxy/smart_proxy_dynflow_core.log # ll /var/log/foreman-proxy/ | grep smart_proxy -rw-r--r--. 1 foreman-proxy foreman-proxy 0 Sep 25 03:36 smart_proxy_dynflow_core.log -rw-r--r--. 1 foreman-proxy foreman-proxy 325 Sep 22 13:11 smart_proxy_dynflow_core.log-20180923.gz -rw-r--r--. 1 foreman-proxy foreman-proxy 260 Sep 24 03:16 smart_proxy_dynflow_core.log-20180924.gz 2. WHEN log file is not empty and performed logrotate, created new empty smart_proxy_dynflow_core.log and log points to correct location. # tail /var/log/foreman-proxy/smart_proxy_dynflow_core.log127.0.0.1 - - [25/Sep/2018:03:46:02 EDT] "GET /console HTTP/1.1" 200 3433 # logrotate /etc/logrotate.conf -f # lsof -p 68199 | grep smart_proxy ruby 68199 foreman-proxy 9w REG 253,0 0 637671073 /var/log/foreman-proxy/smart_proxy_dynflow_core.log # ll /var/log/foreman-proxy/ | grep smart_proxy -rw-r--r--. 1 foreman-proxy foreman-proxy 0 Sep 25 03:46 smart_proxy_dynflow_core.log -rw-r--r--. 1 foreman-proxy foreman-proxy 325 Sep 22 13:11 smart_proxy_dynflow_core.log-20180923.gz -rw-r--r--. 1 foreman-proxy foreman-proxy 260 Sep 24 03:16 smart_proxy_dynflow_core.log-20180924.gz -rw-r--r--. 1 foreman-proxy foreman-proxy 91 Sep 25 03:46 smart_proxy_dynflow_core.log-20180925.gz 3. Performing again logrotate, wont make any changes as smart_proxy_dynflow_core.log was empty and points to correct location. # logrotate /etc/logrotate.conf -f # lsof -p 68199 | grep smart_proxy ruby 68199 foreman-proxy 9w REG 253,0 74 637671073 /var/log/foreman-proxy/smart_proxy_dynflow_core.log 4. If .gz file already exists for same day, and performed logroate it wont create new file/update existing smart_proxy_dynflow_core.log. 5. Destructive test: Removed smart_proxy_dynflow_core.log # lsof -p 68199 | grep smart_proxy ruby 68199 foreman-proxy 9w REG 253,0 74 637671073 /var/log/foreman-proxy/smart_proxy_dynflow_core.log (deleted) # logrotate /etc/logrotate.conf -f # lsof -p 68199 | grep smart_proxy ruby 68199 foreman-proxy 9w REG 253,0 74 637671073 /var/log/foreman-proxy/smart_proxy_dynflow_core.log (deleted) In this case, performing logrotate wont help, servce restart is needed. 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/RHSA-2018:2927 |