application logs should be written to the stdout

[smnbbrv]

Hi guys,

Intro

it's quite a common behavior that all the docker logs are written to STDOUT / STDERR.

https://docs.docker.com/config/containers/logging/

Problem

That's sad but (due to whatever reason) shiny server and shiny application logs are considered to be different. This is fine unless we talk about the docker.

As a developer / devops / administrator I'm way more interested in the applications' rather than shiny-server's logs. In other words, I don't care about shiny server itself, I do care about my application. I want to know when it gets down and, more important, WHY it gets down in a production environment. Shiny-server itself does everything to prevent me from getting this information. The logs are automatically deleted after application fails (but at least I can stop this by a proper setting). Still, there is no option to put application logs to STDOUT / STDERR. The log filenames are always different.

This goes against any logic, it is not production- / cloud-friendly. I cannot use standard tools for collecting the logs and this is painful, e.g. see https://kubernetes.io/docs/concepts/cluster-administration/logging/.

Workarounds

I think mounting a volume is not a good way of getting the logs. First of all, they (again) automatically get deleted. Secondly, this is probably fine for development purposes but for production... It's generally impossible to support this without additional effort and tools.

Proposal

I would be totally satisfied to see all the logs in one thread. If this is not a default behavior - fine, let's enable this with some environment variable.

I found a solution for this and posted it as a pull request #43 . This solution is additionally good because you can always see the filename before the logs => you can easily find which application did log that. The solution is bad because it makes a roundtrip, using the filesystem watcher to see the file changes. Generally, this far away from the best solution, but it is absolutely better than nothing.

Actually I don't see any problem with not merging the PR. It's always enough to extend the Dockerfile with the command from the PR. I simply want other suffering people to find a way around this problem.

Please let me know what you think.

[cboettig]

@smnbbrv thanks for the issue! I definitely see your point and I'm sure other users have hit the same issue you have, just don't want to introduce a change that could break some existing workflow without giving it a bit of a hearing first.

Your approach looks reasonable to me, but like you say, is not ideal either. I don't use Kubernetes much, but it seems like the 'sidecar' approach of using a second container and a bit of volume mapping could also work.

The RStudio folk could probably comment in more detail about why logging works the way it does. I'm mindful of the fact that they also have a commercial Shiny Server Pro product already though, so perhaps it is reasonable that they have a different focus and features in the open source version. (Rocker project has no affiliation with RStudio Inc, but we maintain these images which use their trademarks with their explicit approval).

[smnbbrv]

I understand the possible "commercial" point behind the issue, but we even have a commercial version of shiny-server. It does not help us at all :)

Sidecar container can do that, you are right. There are also some other ways, including the log collection from the mounted volume, problem is that this is kind of not "true" way of doing this.

Look at those (just random query to google it)

https://stackoverflow.com/questions/48864028/logging-json-to-stdout-in-shiny-server
https://community.rstudio.com/t/shiny-server-application-logs-to-standard-out/7713
https://support.rstudio.com/hc/en-us/community/posts/115006997047-Logging-to-stdout

etc. etc. etc.

Honestly, it makes me crying.

Breaking changes are never good. Maybe it makes sense to have a separate image / tag implementing this logic?

P.S. I'm not a "shiny" and not even close to be "R" developer, but even if I was one, looking at the application logs (even mixed with other applications' / shiny server logs) after docker run is way more comfortable than mounting the directory and manually searching for log files. Imagine any other server: python, nodejs, whatsoever would just write everything into single stdout. However, this is just to my taste.

[wch]

Disclaimer: I haven't done development on Shiny Server, so don't take what I say here as canon. That said, I believe the main reason that it writes logs to separate files is so that, if there are multiple users with their own Shiny applications, each user can see the content of their own log files, but no one else's. That's probably not a concern in most Docker-based deployments.

I believe Shiny Server Pro does logging the same way.

[guglez]

Hi @cboettig,

I believe that the method suggested by @smnbbrv is a right appoach of building docker containers. By default I expect that with docker all logs will go to stdout/stderr. Docker has a nice article which covers the topic raised by @smnbbrv : https://success.docker.com/article/logging-best-practices

If the application has custom logging ( e.g. writes logs to /var/log/myapp.log within the container), it's important to take that into consideration.

We are facing same issues since we started to use docker for hosting our shiny apps. I believe that the fix proposed in #43 can make our lives easier.

[eddelbuettel]

Dunno. This leaves me a little torn. The behaviour we witness is upstream behaviour, and it has its uses (ie splitting by shiny users). Tailing the log to stdout seems like a hack to me, rather than a fix.

Maybe there is a more fundamental issue here that if an when you have such logging requirements, shiny-via-docker may not be the best solution and running natively may be preferable.

That said, this part of Rocker is much more owned by @cboettig and @wch so I definitely defer to their judgment. Just wanted to state that this solution leaves me a little underwhelmed but I also have not studied all aspect in the fullest detail.

(Also you URL link went nowhere as a markdown link. I edited that.)

[smnbbrv]

I think the issue is a bit overdramatised here. I've added an environment variable that should be explicitly set up in order to enable this mode.

if [ "$APPLICATION_LOGS_TO_STDOUT" = "true" ];
then
    echo "All application logs will be printed to STDOUT"

    # start shiny server in detached mode
    exec shiny-server 2>&1 &

    # push the "real" application logs to stdout with xtail
    exec xtail /var/log/shiny-server/
else
    exec shiny-server 2>&1
fi

The default behaviour remains the same. The mode is explicitly marked as experimental in the README.md, so everything is on the safe side.

The only issue left is the fact that xtail is probably not the best solution out there. However, as long as this is masked by APPLICATION_LOGS_TO_STDOUT it could be changed any day to anything else.

Are there other issues you guys can see?

[eddelbuettel]

Correct me if I am wrong ... but that very behaviour you now describe was added in the last 30 minutes in response to our comments. Or am I missing something here?

[smnbbrv]

you are absolutely right. I did not say the opposite :) Still, I did not invent this right now, this was originally proposed but for some reason did not receive enough attention:

I would be totally satisfied to see all the logs in one thread. If this is not a default behavior - fine, let's enable this with some environment variable.

That's why I just added it because I feel we will never agree on anything otherwise

[eddelbuettel]

Agree that the environment variable switch is better and less invasive.

Question now is whether it belongs into our container, with all the needed extra documentation. All that is more or less obfuscation for normal users brought on for your use case. Don't get me wrong -- we hear you. But these containers have proven to be more than mildly popular and we get request about special use case just about every week or other week. We must draw a line somewhere and can only accept what is clearly useful for large enough a set of users.

[smnbbrv]

This is fair. As long as you are supporting it, the decision, of course, should be taken by you.

[cboettig]

@smnbbrv Thanks for the engagement, I appreciate you raising this issue and think it's worth getting right. I did see your earlier note about possibly going the env var route to make this opt in, and I suspect that's the safest option in case any existing users protest at the change in behavior. But we haven't seen any comments to that effect so far, and it does seem that the current logging situation, as much as it is consistent with the standard behavior of Shiny, does confuse people in and and outside of docker.

So, I think the best solution might actually be to make your proposal the default behavior, and use the env var to opt out to the old behavior, rather than the reverse. This makes the simpler and more standard docker approach the default instead of assuming the users will all read the docs carefully ;-), but also gives existing systems a way to get the old separate behavior back if they want. How does that sound?

Would you be willing to update the pull request this way, and update the README?

[cboettig]

closed by #43

[smnbbrv]

@cboettig when can we test the changes? The image does not seem to be updated yet

[cboettig]

@smnbbrv thanks for the ping, looks like my cron triggers for shiny weren't set up yet. (latest and devel should build nightly, version tagged image should build monthly now).