Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix(cli) stop redirecting output when not starting as a daemon #3297

Closed
wants to merge 2 commits into from
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
21 changes: 16 additions & 5 deletions kong/cmd/utils/nginx_signals.lua
Original file line number Diff line number Diff line change
Expand Up @@ -84,13 +84,24 @@ function _M.start(kong_conf)

log.debug("starting nginx: %s", cmd)

local ok, _, _, stderr = pl_utils.executeex(cmd)
if not ok then
return nil, stderr
if kong_conf.nginx_daemon == "on" then
-- running as daemon, so we capture command output to temp files using
-- the "executeex" method
local ok, _, _, stderr = pl_utils.executeex(cmd)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just below this line, should print the stdout of nginx? Either here or in the not ok path. The rationale would be to give a more "native" feeling to the user (with print, not with log), so the output looks barefeet from nginx itself. What do you think?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Probably not - if we're running in daemon mode, let's stay consistent with today's behavior, little value in this.

if not ok then
return nil, stderr
end
log.debug("nginx started")

else
-- not as a dameon, so we cannot redirect because in long running processes
-- the output will fill the disk. Use "execute" without redirection instead.
local ok, retcode = pl_utils.execute(cmd)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Since we only target one Lua version (LuaJIT), there's no need to use pl_utils.execute here, one can just use os.execute directly (and handle the Lua 5.1 semantics of the results).

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I know, but since we use PL everywhere, I'd rather stay consistent. Lmk if you want me to change it.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not a blocker by any means -- I just noted the added cognitive step (I had to look into Penlight to check if utils.execute did anything else surprising like executeex does; I wouldn't have to if it was os.execute)

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@hisham How about any side effects? I'm not very familiar with the underlying unix structures (was surprised by the bug at all), so that's what I'm mostly concerned about.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@hishamhm

Not a blocker by any means -- I just noted the added cognitive step (I had to look into Penlight to check if utils.execute did anything else surprising like executeex does; I wouldn't have to if it was os.execute)

Had to go look for it, see this PR by @bungle . We had issues before. We only support LuaJIT, but that behaves differently based on the 52 compat-flag (compile time).

So we learned the hard way (but apparently not hard enough since I didn't remember 😄 ).

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Agreed - better to keep pl_utils.execute, the compat flag was a nightmare to get out of...

We should be adding a test for the foreground mode, asserting that we see Nginx's stdout/stderr logs...

if not ok then
return nil, ("failed to start nginx (exit code: %s)"):format(tostring(retcode))
end
end

log.debug("nginx started")

return true
end

Expand Down
116 changes: 116 additions & 0 deletions spec/02-integration/02-cmd/02-start_stop_spec.lua
Original file line number Diff line number Diff line change
@@ -1,4 +1,6 @@
local helpers = require "spec.helpers"
local pl_utils = require "pl.utils"
local pl_path = require "pl.path"

describe("kong start/stop", function()
setup(function()
Expand Down Expand Up @@ -39,6 +41,120 @@ describe("kong start/stop", function()
assert(helpers.kong_exec("start --conf " .. helpers.test_conf_path))
assert.truthy(helpers.path.exists(helpers.test_conf.kong_env))
end)
it("#only start without daemonizing will properly log to stdout/stderr", function()
--[[
What are we testing exactly?
When Kong starts, the cli commands will shell out to start the 'nginx'
executable. The stdout/stderr of this command is redirected to be captured
in case of errors.
A problem arises when Kong runs in the foreground 'nginx_daemon=off', and
the nginx log output is set to '/dev/stderr' and '/std/stdout'.
In this case the shell command to start Kong will capture all output send
to stdout/stderr by nginx. Which causes the tempfiles to grow uncontrolable.

So when Kong is run in the foreground, no redirects should be used when
starting Kong to prevent the above from happening. Or in other words we
want the stdout/stderr of the "kong start" command to receive all output
of the nginx logs. Instead of them being swallowed by the intermediary
nginx start command (used by "kong start" under the hood).
--]]
local exec = os.execute -- luacheck: ignore
local stdout = pl_path.tmpname()
local stderr = pl_path.tmpname()
-- create a finalizer that will stop Kong and cleanup logfiles
finally(function()
os.remove(stdout)
os.remove(stderr)
os.execute = exec -- luacheck: ignore
assert(helpers.kong_exec("stop", {
prefix = helpers.test_conf.prefix,
}))
end)
-- catch the prepared start command (let the 'helpers' do
-- the hard work of building the command)
local start_cmd
os.execute = function(cmd) start_cmd = cmd return true end -- luacheck: ignore
assert(helpers.kong_exec("start", {
prefix = helpers.test_conf.prefix,
database = helpers.test_conf.database,
pg_database = helpers.test_conf.pg_database,
cassandra_keyspace = helpers.test_conf.cassandra_keyspace,
proxy_listen = "127.0.0.1:" .. helpers.test_conf.proxy_listeners[1].port,
admin_listen = "127.0.0.1:" .. helpers.test_conf.admin_listeners[1].port,
admin_access_log = "/dev/stdout",
admin_error_log = "/dev/stderr",
proxy_access_log = "/dev/stdout",
proxy_error_log = "/dev/stderr",
log_level = "debug",
nginx_daemon = "off",
}))
os.execute = exec -- luacheck: ignore
-- remove the stdout/stderr redirects from the captured command
-- and insert new ones for us to track
start_cmd = start_cmd:match("^(.- bin/kong start).-$")
start_cmd = start_cmd .. " > " .. stdout .. " 2> " .. stderr
start_cmd = start_cmd .. " &" -- run it detached
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I wonder if would it make sense to add a feature in helpers.start_kong to make it do that, instead of making the test rely on knowledge of its internals.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

we have that, but it runs Kong as a daemon. And in this case we cannot use that since we run in foreground, and then that call would block, stopping the tests.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I meant adding a flag to start_kong that adds the redirects and &... but at this point I'm still wondering if it's all worth it. As we discussed earlier, this is probably going to remain a fragile test for a very edge case... Would like to hear more opinions!

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think the following test case is a lot more concise and reliable:

  it("#oo", function()
    local pl_utils = require "pl.utils"
    local pl_file = require "pl.file"

    local stdout_path = os.tmpname()

    finally(function()
      os.remove(stdout_path)
    end)

    local cmd = string.format("KONG_PROXY_ACCESS_LOG=/dev/stdout "    ..
                              "KONG_NGINX_DAEMON=off %s start -c %s " ..
                              ">%s 2>/dev/null &", helpers.bin_path,
                              helpers.test_conf_path, stdout_path)

    local ok, _, _, stderr = pl_utils.executeex(cmd)
    if not ok then
      error(stderr)
    end

    do
      local proxy_client

      -- get a connection, retry until kong starts
      helpers.wait_until(function()
        proxy_client = helpers.proxy_client()
        return true
      end)

      local res = assert(proxy_client:send {
        method = "GET",
        path = "/hello",
      })
      assert.res_status(404, res) -- no API configured
    end

    assert(helpers.stop_kong(helpers.test_conf.prefix))

    -- TEST: since nginx started in the foreground, the 'kong start' command
    -- stdout should receive all of nginx's stdout as well.
    local stdout = pl_file.read(stdout_path)
    assert.matches([["GET /hello HTTP/1.1" 404]] , stdout, nil, true)
  end)

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, I like this a lot better!

-- Now start Kong non-daemonized, but detached
assert(pl_utils.execute(start_cmd))
-- wait for Kong to be up and running, create a test service
helpers.wait_until(function()
local success, admin_client = pcall(helpers.admin_client)
if not success then
--print(admin_client)
return false
end
local res = assert(admin_client:send {
method = "POST",
path = "/services",
body = {
name = "my-service",
host = "127.0.0.1",
port = helpers.test_conf.admin_listeners[1].port,
},
headers = {["Content-Type"] = "application/json"}
})
admin_client:close()
--print(res.status)
return res.status == 201
end, 60)
-- add a test route
helpers.wait_until(function()
local success, admin_client = pcall(helpers.admin_client)
if not success then
--print(admin_client)
return false
end
local res = assert(admin_client:send {
method = "POST",
path = "/services/my-service/routes",
body = {
paths = { "/" },
},
headers = {["Content-Type"] = "application/json"}
})
admin_client:close()
--print(res.status)
return res.status == 201
end, 10)
-- make at least 1 succesful proxy request
helpers.wait_until(function()
-- make a request on the proxy port
local proxy_client = helpers.proxy_client()
local res = assert(proxy_client:send {
method = "GET",
path = "/",
})
proxy_client:close()
--print(res.status)
return res.status == 200
end, 10)
-- fetch the log files we set
local logout = assert(pl_utils.readfile(stdout))
local logerr = assert(pl_utils.readfile(stderr))
-- validate that the output contains the expected log messages
assert(logerr:find("load_plugins(): Discovering used plugins", 1, true))
assert(logout:find('"GET / HTTP/1.1" 200 ', 1, true))
end)
it("creates prefix directory if it doesn't exist", function()
finally(function()
helpers.kill_all("foobar")
Expand Down