Added log prefixes #444

scriptcoded · 2020-03-03T06:26:30Z

In response to #442

Quirks that might be unfavorable:

Requires importing start-utils in every file
Requires the use of log insteadofecho`
[wrapper] tag is configurable in the start-utils file, but [minecraft] is repeated twice in start-minecraftFinalSetup and has no config.

I had some thought about configuration, but my own opinion is that logger names shouldn't have to be configurable from the user side. I can't see a case where the user would benefit from changing the logger names, as long as they are kept unique.

These changes have really just served as a workaround for personal use, so please, rip them all out if need be :)

wlp7s0 · 2020-03-03T11:26:14Z

@scriptcoded this is tremendous work. And it will be a problem to change it in the feature. I suggest using bash alias to do this job. It will require 2 lines added. What do you think? smth like this:

add global alias for bash for next scrips to use it
echo 'alias echo="echo -e \"\033[0;34m[wrapper]\033[0m $*\""' >> ~/.bashrc
actually use this alias in this script too, because .bashrc will not be executed here anymore.
alias echo="echo -e \"\033[0;34m[wrapper]\033[0m $*\""
at the beginning of the
start file.

itzg

Thanks! I like the overall approach and normally I would prefer the clarity of a log function; however, given that so many lines had to be touched, I like the sound of @wlp7s0 's suggestion number 2 about aliasing echo. I'm good with including start-utils in every file, so just declare the alias there and keep those inclusion changes you have made.

@wlp7s0 how strongly do you feel about the escape codes in your suggestion? I'd prefer to keep the log prefix plain text since non-console/tty environments are common, such as kubernetes deployments.

itzg · 2020-03-03T15:32:02Z

start-minecraftFinalSetup

  JVM_OPTS="-Xms${INIT_MEMORY} -Xmx${MAX_MEMORY} ${JVM_OPTS}"
  if isTrue ${DEBUG_EXEC}; then
    set -x
  fi
-  exec mc-server-runner ${bootstrapArgs} ${mcServerRunnerArgs} java $JVM_XX_OPTS $JVM_OPTS $expandedDOpts -jar $SERVER "$@" $EXTRA_ARGS
+  exec mc-server-runner ${bootstrapArgs} ${mcServerRunnerArgs} java $JVM_XX_OPTS $JVM_OPTS $expandedDOpts -jar $SERVER "$@" $EXTRA_ARGS | sed "s/^/[minecraft] /"


Since it's an exec I'm not sure if piping to sed actually works...or worse, it might default the point of the exec and insert a shell process as a parent of mc-server-runner process. Can you provide a ps -ef of a container running with these changes so I can confirm the process tree?

It works for sure. At least my output looks perfectly fine:

2020-03-03T16:30:15.739032751Z [wrapper] Copying any mods over... 2020-03-03T16:30:15.742490670Z [wrapper] Setting initial memory to 1G and max to 1G 2020-03-03T16:30:15.742728666Z [wrapper] Starting the Minecraft server... 2020-03-03T16:30:18.490584942Z [minecraft] [16:30:18] [main/INFO]: Loading for game Minecraft 1.15.2 2020-03-03T16:30:18.563249509Z [minecraft] [16:30:18] [main/INFO]: [FabricLoader] Loading 2 mods: minecraft@1.15.2, fabricloader@0.7.8+build.184

As for how it actually runs:

$ docker exec 8234897ee6ee ps -ef PID USER TIME COMMAND 1 minecraf 0:00 {start-minecraft} /bin/bash /start-minecraftFinalSetup 38 minecraf 0:00 mc-server-runner --stop-duration 60s java -XX:+UseG1GC -Xms1G -Xmx1G -jar fabric-server-launch.jar 39 minecraf 0:00 sed s/^/[minecraft] / 46 minecraf 1:24 java -XX:+UseG1GC -Xms1G -Xmx1G -jar fabric-server-launch.jar 106 root 0:00 ps -ef

I'll be perfectly honest and say that I don't quite follow what issues might arise from doing it the way I'm doing it. Are you thinking about performance?

Sorry, I didn't realize ps by default on alpine doesn't show the parent PID of each process. Please re-run with

ps -ef -o pid,ppid,args

The problem I'm worried about is signal propagation, specifically the SIGTERM when the container is stopped. The main reason I created mc-server-runner was to intercept the SIGTERM and send a stop command to gracefully stop the minecraft server since it itself doesn't properly handle SIGTERM. This article explains it pretty nicely.

For comparison, here's what the process tree looks like on master:

PID PPID COMMAND 1 0 mc-server-runner --stop-duration 60s java -XX:+UseG1GC -Xms1G -Xmx1G -jar minecraft_server.1.15.2.jar 56 1 java -XX:+UseG1GC -Xms1G -Xmx1G -jar minecraft_server.1.15.2.jar

where mc-server-runner must become PID 1 to intercept the signals.

So...long story, short, I think it'll take an enhancement in mc-server-runner to properly prepend those logs. FWIW, I have been wanting to enrich those logs with a date, in addition to time, so that would be a reasonable modification.

start-user

itzg · 2020-03-03T15:33:51Z

start-utils

  fi
 }
+
+function log {
+  echo "[wrapper] $*"


I'm good with hardcoding this; however, "wrapper" still doesn't feel right to me. How about "[startup]" or "[init]"?

[init] sound good in my ears. Even better would be to perhaps have something more descriptive. I can't figure out a good name though, since [minecraft-server] would indicate the actual Minecraft server.

scriptcoded · 2020-03-03T16:25:21Z

@scriptcoded this is tremendous work. And it will be a problem to change it in the feature. I suggest using bash alias to do this job. It will require 2 lines added. What do you think? smth like this:

add global alias for bash for next scrips to use it
echo 'alias echo="echo -e \"\033[0;34m[wrapper]\033[0m $*\""' >> ~/.bashrc

actually use this alias in this script too, because .bashrc will not be executed here anymore.
alias echo="echo -e \"\033[0;34m[wrapper]\033[0m $*\""
at the beginning of the
start file.

I personally feel very strongly about modifying native functionality. However, I understand that large changes like my proposal might be unwanted. I guess it boils down to personal preference, and after all this is @itzg's project.

@itzg As for escape codes they make parsing the output very cumbersome. Perhaps adding a flag to enable colorized output would be a solution?

wlp7s0 · 2020-03-03T16:41:22Z

@itzg oh, yeah. You are correct, no need to colourize the output. Didn't think about no-tty deploys.

@scriptcoded I would really like to understand what do you mean by

modifying native functionality

I would like to know it from my personal perspective. I don't see any problem with modifying bashrc inside the container. May be my approach is bad? Can you elaborate please? Because for me it is more like configuring the environment rather than changing functionality.

scriptcoded · 2020-03-03T16:54:18Z

@wlp7s0 I like to be careful changing behaviors that are standard. For example, echo outputs a raw line of text with line break at the end. Let's say that a script uses something like the following:

echo "foo" >> bar.txt

You would expect bar.txt to contain foo, but instead it will contain [init] foo. It might not be a problem in this case. It's a rather small project after all, and @itzg will probably be there checking all PRs, but I still find it to be a bad practice changing behaviors that are taken for granted.

wlp7s0 · 2020-03-03T17:08:53Z

@scriptcoded I see. This is true, but after modifying global alias, this behaviour is expected. Thank you for the explanation.

itzg · 2020-03-03T17:24:29Z

Yeah, all in all I prefer the log usage even if it did mean a lot of little changes. If you'll tweak the log prefix I'm good to approve and merge this.

scriptcoded · 2020-03-03T18:07:11Z

@itzg I'll do that. Did we settle on "init"?

itzg · 2020-03-03T19:35:08Z

“init” works for me

itzg

When testing the PR branch I found that the minecraft server failed early with a complaint about the eula.

Build/running with docker build -t mc . && docker run -it --rm -e EULA=TRUE --name mc mc I got

[init] Starting the Minecraft server...
2020/03/04 15:35:48 Done
[minecraft] [15:35:48] [main/INFO]: You need to agree to the EULA in order to run the server. Go to eula.txt for more info.

With some debugging I discovered the eula file was getting the logging prefixes too:

[init] # Generated via Docker on Wed Mar  4 15:33:38 UTC 2020
[init] eula=true

With that discovery I re-reviewed and noted items that need to remain an echo. Sorry I missed that in my initial review.

start

start-configuration

start-deployFabric

start-deployForge

start-finalSetup04ServerProperties

start-minecraftFinalSetup

itzg · 2020-03-04T15:55:24Z

start-minecraftFinalSetup

  JVM_OPTS="-Xms${INIT_MEMORY} -Xmx${MAX_MEMORY} ${JVM_OPTS}"
  if isTrue ${DEBUG_EXEC}; then
    set -x
  fi
-  exec mc-server-runner ${bootstrapArgs} ${mcServerRunnerArgs} java $JVM_XX_OPTS $JVM_OPTS $expandedDOpts -jar $SERVER "$@" $EXTRA_ARGS
+  exec mc-server-runner ${bootstrapArgs} ${mcServerRunnerArgs} java $JVM_XX_OPTS $JVM_OPTS $expandedDOpts -jar $SERVER "$@" $EXTRA_ARGS | sed "s/^/[minecraft] /"


Sorry, I didn't realize ps by default on alpine doesn't show the parent PID of each process. Please re-run with

ps -ef -o pid,ppid,args

The problem I'm worried about is signal propagation, specifically the SIGTERM when the container is stopped. The main reason I created mc-server-runner was to intercept the SIGTERM and send a stop command to gracefully stop the minecraft server since it itself doesn't properly handle SIGTERM. This article explains it pretty nicely.

For comparison, here's what the process tree looks like on master:

PID PPID COMMAND 1 0 mc-server-runner --stop-duration 60s java -XX:+UseG1GC -Xms1G -Xmx1G -jar minecraft_server.1.15.2.jar 56 1 java -XX:+UseG1GC -Xms1G -Xmx1G -jar minecraft_server.1.15.2.jar

where mc-server-runner must become PID 1 to intercept the signals.

So...long story, short, I think it'll take an enhancement in mc-server-runner to properly prepend those logs. FWIW, I have been wanting to enrich those logs with a date, in addition to time, so that would be a reasonable modification.

start-deployBukkitSpigot

scriptcoded · 2020-03-05T07:35:42Z

@itzg (couldn't reply to your comment for some reason)

Your suspicion was correct, and the process tree becomes odd:

PID   PPID  COMMAND
    1     0 {start-minecraft} /bin/bash /start-minecraftFinalSetup
   50     1 mc-server-runner --stop-duration 60s java -XX:+UseG1GC -Xms1G -Xmx1G -jar minecraft_server.1.15.2.jar
   51     1 sed s/^/[minecraft] /
   58    50 java -XX:+UseG1GC -Xms1G -Xmx1G -jar minecraft_server.1.15.2.jar

I'm getting the same output as you if I remove the sed.

After having looked up a bit more about signal propagation, I agree that the best place to add it would be in mc-server-runner.

When it comes to timestamp, docker logs -t will show output with timestamps. I guess the benefit from adding timestamps to mc-server-runner would be to have them show in docker run and perhaps to remove the potential delay from actual log to timestamp appending. That's a discussion for another thread though.

itzg · 2020-03-05T11:46:50Z

Ah, I didn’t know docker logs has that -t option. In that case, would filtering away the “init” lines be good enough to pick out the Minecraft server logs for your purposes?

scriptcoded · 2020-03-05T15:27:06Z

@itzg Just having [init] would be enough for my own purposes, yes. It might be nice for the sake of the project to have consistent logs though. But I think that for any solution that has to parse the logs, just having that [init] would be plenty good.

scriptcoded · 2020-03-06T13:54:04Z

I think we're ready for this feature to be merged now. Sorry for making this take so long!

itzg · 2020-03-06T15:37:58Z

I think we're ready for this feature to be merged now. Sorry for making this take so long!

No problem at all. Thanks for working with me on this one.

itzg

Retested the latest code and server startup looks good and process-tree is good. Thanks again!

itzg · 2020-03-06T16:12:54Z

The updated image is now on Docker Hub.

Added log prefixes

6b9e579

itzg reviewed Mar 3, 2020

View reviewed changes

Removed leftover file

0b4e2de

Changed name of log prefix

549d9b3

scriptcoded requested a review from itzg March 3, 2020 20:01

itzg requested changes Mar 4, 2020

View reviewed changes

scriptcoded commented Mar 5, 2020

View reviewed changes

start-deployBukkitSpigot Outdated Show resolved Hide resolved

Reverted to echo for redirected outputs

070fff7

Reverted Spigot build echo

633b482

scriptcoded added 2 commits March 6, 2020 14:51

Moved newline logic for log func to new func

394ced1

Removed Minecraft server log prefix

594a809

itzg approved these changes Mar 6, 2020

View reviewed changes

itzg merged commit 1e334ca into itzg:master Mar 6, 2020

scriptcoded mentioned this pull request Mar 6, 2020

Log prefix #442

Closed

itzg mentioned this pull request May 22, 2020

Autopause functionality #531

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Added log prefixes #444

Added log prefixes #444

scriptcoded commented Mar 3, 2020

wlp7s0 commented Mar 3, 2020 •

edited

Loading

itzg left a comment

itzg Mar 3, 2020

scriptcoded Mar 3, 2020

itzg Mar 4, 2020

itzg Mar 3, 2020

scriptcoded Mar 3, 2020

scriptcoded commented Mar 3, 2020

wlp7s0 commented Mar 3, 2020 •

edited

Loading

scriptcoded commented Mar 3, 2020 •

edited

Loading

wlp7s0 commented Mar 3, 2020

itzg commented Mar 3, 2020

scriptcoded commented Mar 3, 2020

itzg commented Mar 3, 2020

itzg left a comment

itzg Mar 4, 2020

scriptcoded commented Mar 5, 2020

itzg commented Mar 5, 2020

scriptcoded commented Mar 5, 2020

scriptcoded commented Mar 6, 2020

itzg commented Mar 6, 2020

itzg left a comment

itzg commented Mar 6, 2020

Added log prefixes #444

Added log prefixes #444

Conversation

scriptcoded commented Mar 3, 2020

wlp7s0 commented Mar 3, 2020 • edited Loading

itzg left a comment

Choose a reason for hiding this comment

itzg Mar 3, 2020

Choose a reason for hiding this comment

scriptcoded Mar 3, 2020

Choose a reason for hiding this comment

itzg Mar 4, 2020

Choose a reason for hiding this comment

itzg Mar 3, 2020

Choose a reason for hiding this comment

scriptcoded Mar 3, 2020

Choose a reason for hiding this comment

scriptcoded commented Mar 3, 2020

wlp7s0 commented Mar 3, 2020 • edited Loading

scriptcoded commented Mar 3, 2020 • edited Loading

wlp7s0 commented Mar 3, 2020

itzg commented Mar 3, 2020

scriptcoded commented Mar 3, 2020

itzg commented Mar 3, 2020

itzg left a comment

Choose a reason for hiding this comment

itzg Mar 4, 2020

Choose a reason for hiding this comment

scriptcoded commented Mar 5, 2020

itzg commented Mar 5, 2020

scriptcoded commented Mar 5, 2020

scriptcoded commented Mar 6, 2020

itzg commented Mar 6, 2020

itzg left a comment

Choose a reason for hiding this comment

itzg commented Mar 6, 2020

wlp7s0 commented Mar 3, 2020 •

edited

Loading

wlp7s0 commented Mar 3, 2020 •

edited

Loading

scriptcoded commented Mar 3, 2020 •

edited

Loading