[SERVER-2246] No puppet compiler logs with STDOUT logback logging Created: 2018/07/09  Updated: 2018/07/17  Resolved: 2018/07/17

Status: Closed
Project: Puppet Server
Component/s: Puppet Server
Affects Version/s: SERVER 5.3.3
Fix Version/s: None

Type: Bug Priority: Normal
Reporter: Thomas Mueller Assignee: Thomas Mueller
Resolution: Cannot Reproduce Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

RHEL 7 with Systemd


Template: PUP Bug Template
Acceptance Criteria:

Configuring logback to with ConsoleAppender (STDOUT) shows the same messages as logging with RollingFileAppender (/var/log/pupetlabs/puppetserver/puppetserver.log)

Method Found: Needs Assessment
QA Risk Assessment: Needs Assessment

 Description   

Puppet Version: 5.5.3
Puppet Server Version: 5.3.3
OS Name/Version: RHEL 7

Steps to reproduce:

  • Add STDOUT appender-ref to logback.xml:

<configuration>
...
<root level="info">
  ...
  <appender-ref ref="STDOUT" />
</root>
</configuration>

  • restart puppetserver systemd service
  • watch puppetserver STDOUT output with journalctl -u puppetserver.service
  • compare with /var/log/puppetlabs/puppetserver/puppetserver.log

Actual Behavior:

all Puppet compiler messages are missing on STDOUT

Some example messages not added to STDOUT:

Pupppet The function 'xy' is deprecated in favor of using 'lookup' ...
Puppet This method is deprecated, please use the ...
Puppet Undefined variable '...' ...
Puppet Compiled catalog for ... in environment .... in ... seconds

Desired Behavior:
same logs on STDOUT as in /var/log/puppetlabs/puppetserver/puppetserver.log

solution:

journalctl -u puppetserver.service only includes messages until puppserver service is started. The java process stdout is still captured and logged to jouranld.

Use journalctl -t puppetserver to get the logs.



 Comments   
Comment by Justin Stoller [ 2018/07/10 ]

How did you start puppetserver? Using the puppetserver start or systemctl start puppetserver will put the process in the background so STDOUT for the process is not attached to your terminal and you won't see it. There is a puppetserver foreground command that will not background the process and should let you see the processes STDOUT in your terminal.

Comment by Thomas Mueller [ 2018/07/10 ]

Justin Stoller sorry, indeed I forgot to write about how i started the service what seems to be the important part here. :-/
this was by systemctl start/stop/restart puppetserver. the STDOUT output I meant the process output captured by systemd that is saved to journald (which is also forwarded to localhost syslog).

As you write will put the service in the background I think this is my problem here. it will close/redirect stderr/stdout to somewhere else?

So maybe I'm not looking the ConsoleAppender feature but something that can write to /dev/log which also seems to listend by journald.

Comment by Thomas Mueller [ 2018/07/10 ]

comparing /opt/puppetlabs/server/apps/puppetserver/cli/apps/foreground and /opt/puppetlabs/server/apps/puppetserver/cli/apps/start starting command:

${JAVA_BIN} ${JAVA_ARGS} -Djava.security.egd=/dev/urandom \
	  -XX:OnOutOfMemoryError="kill -9 %p" \
	  -cp "${CLASSPATH}" \
	  clojure.main \
	  -m puppetlabs.trapperkeeper.main \
	  --config "${CONFIG}" \
	  --bootstrap-config "${BOOTSTRAP_CONFIG}" \
	  --restart-file "${restartfile}" &

and foreground:

COMMAND="${JAVA_BIN} ${JAVA_ARGS} ${LOG_APPENDER} \
         -Djava.security.egd=/dev/urandom \
         -cp "$CLASSPATH" \
         clojure.main -m puppetlabs.trapperkeeper.main \
         --config ${CONFIG} --bootstrap-config ${BOOTSTRAP_CONFIG} \
         --restart-file "${restartfile}" \
         ${@}"

the start backgrounds the task whereas foreground does not. But I can't see closing stdout/stderr anywhere in the shell script. So I somehow expect STDOUT should still be available for the java process and thus ConsoleAppender might work.

I was looking for SyslogAppender to write to /dev/log but the only thing I could find by googling was that logback does not support to write to a unix-socket.

Comment by Justin Stoller [ 2018/07/10 ]

Okay, I'm not sure if this is would be an issue with the defaults in /etc/sysconfig/puppetserver or the service file and where that might have changed recently. I'll spin up a few versions of the server in the next couple of days to test that out.

You specifically mention the compiler output, are you seeing much else from the server? Wondering if this could be a change within the Puppet compiler/logger so it no longer respects the server's logging.

Comment by Thomas Mueller [ 2018/07/10 ]

To prove my assumption that the stdout of a forked process really is captured in journald I've created a dummy stdout service situation:

#> cat /bin/dummystdout-init 
#!/bin/bash
 
if [ "$1" == "start" ]; then
  dummystdout &
  pid=$!
  echo "Started $pid ..."
  echo $pid >/run/dummystdout.pid
fi
 
if [ "$1" == "stop" ]; then
  kill $(cat /run/dummystdout.pid)
  echo "Killed $pid ..."
  rm /run/dummystdout.pid
fi
 
#>  cat /bin/dummystdout
#!/bin/bash
 
while true; do
  echo "Alive $(date)"
  sleep 2
done
 
#> cat /etc/systemd/system/dummystdout.service 
[Unit]
Description=dummystdout service
 
[Service]
Type=forking
ExecStart=/bin/dummystdout-init start
ExecStop=/bin/dummystdout-init stop

the output keeps going on:

#>  systemctl status dummystdout.service 
● dummystdout.service - dummystdout service
   Loaded: loaded (/etc/systemd/system/dummystdout.service; static; vendor preset: disabled)
   Active: active (running) since Wed 2018-07-11 04:53:05 UTC; 4min 52s ago
  Process: 14494 ExecStart=/bin/dummystdout-init start (code=exited, status=0/SUCCESS)
 Main PID: 14495 (dummystdout)
   CGroup: /system.slice/dummystdout.service
           ├─14495 /bin/bash /usr/bin/dummystdout
           └─14839 sleep 2
 
Jul 11 04:57:40 el7 dummystdout-init[14494]: Alive Wed Jul 11 04:57:40 UTC 2018
Jul 11 04:57:42 el7 dummystdout-init[14494]: Alive Wed Jul 11 04:57:42 UTC 2018
Jul 11 04:57:44 el7 dummystdout-init[14494]: Alive Wed Jul 11 04:57:44 UTC 2018
Jul 11 04:57:46 el7 dummystdout-init[14494]: Alive Wed Jul 11 04:57:46 UTC 2018
Jul 11 04:57:48 el7 dummystdout-init[14494]: Alive Wed Jul 11 04:57:48 UTC 2018
Jul 11 04:57:50 el7 dummystdout-init[14494]: Alive Wed Jul 11 04:57:50 UTC 2018
Jul 11 04:57:52 el7 dummystdout-init[14494]: Alive Wed Jul 11 04:57:52 UTC 2018
Jul 11 04:57:54 el7 dummystdout-init[14494]: Alive Wed Jul 11 04:57:54 UTC 2018
Jul 11 04:57:56 el7 dummystdout-init[14494]: Alive Wed Jul 11 04:57:56 UTC 2018
Jul 11 04:57:58 el7 dummystdout-init[14494]: Alive Wed Jul 11 04:57:58 UTC 2018
 
#> journalctl -u dummystdout.service -n
-- Logs begin at Thu 2018-06-28 19:57:37 UTC, end at Wed 2018-07-11 04:58:42 UTC. --
Jul 11 04:58:24 el7 dummystdout-init[14494]: Alive Wed Jul 11 04:58:24 UTC 2018
Jul 11 04:58:26 el7 dummystdout-init[14494]: Alive Wed Jul 11 04:58:26 UTC 2018
Jul 11 04:58:28 el7 dummystdout-init[14494]: Alive Wed Jul 11 04:58:28 UTC 2018
Jul 11 04:58:30 el7 dummystdout-init[14494]: Alive Wed Jul 11 04:58:30 UTC 2018
Jul 11 04:58:32 el7 dummystdout-init[14494]: Alive Wed Jul 11 04:58:32 UTC 2018
Jul 11 04:58:34 el7 dummystdout-init[14494]: Alive Wed Jul 11 04:58:34 UTC 2018
Jul 11 04:58:36 el7 dummystdout-init[14494]: Alive Wed Jul 11 04:58:36 UTC 2018
Jul 11 04:58:38 el7 dummystdout-init[14494]: Alive Wed Jul 11 04:58:38 UTC 2018
Jul 11 04:58:40 el7 dummystdout-init[14494]: Alive Wed Jul 11 04:58:40 UTC 2018
Jul 11 04:58:42 el7 dummystdout-init[14494]: Alive Wed Jul 11 04:58:42 UTC 2018

Comment by Thomas Mueller [ 2018/07/10 ]

Justin Stoller I found my error :-/ . journalctl -u puppetserver.service only shows lines logged upto when the service enters started state.

the Puppet compiler messages actually get logged to /var/log/messages and also can be queried by journalctl -t puppetserver

from journalctl help: -t --identifier=STRING Show entries with the specified syslog identifier

example:

#> journalctl -u puppetserver.service -n
-- Logs begin at Thu 2018-06-28 19:57:37 UTC, end at Wed 2018-07-11 05:47:02 UTC. --
Jul 11 05:39:57 el7 puppetserver[19437]: 2018-07-11 05:39:57,990 INFO  [async-dispatch-2] [o.e.j.s.AbstractConnector] Started ServerConnector@4bb24e1e{SSL,[ssl, http/1.1]}{0.0.0.0:8140}
Jul 11 05:39:57 el7 puppetserver[19437]: 2018-07-11 05:39:57,990 INFO  [async-dispatch-2] [o.e.j.s.Server] Started @66789ms
Jul 11 05:39:58 el7 puppetserver[19437]: 2018-07-11 05:39:58,000 INFO  [async-dispatch-2] [p.t.s.s.status-core] Starting background monitoring of cpu usage metrics
Jul 11 05:39:58 el7 puppetserver[19437]: 2018-07-11 05:39:58,026 INFO  [async-dispatch-2] [p.t.s.s.status-service] Registering status callback function for service 'status-service', version 1.0.0
Jul 11 05:39:58 el7 puppetserver[19437]: 2018-07-11 05:39:58,026 INFO  [async-dispatch-2] [p.t.s.s.status-service] Registering status service HTTP API at /status
Jul 11 05:39:58 el7 puppetserver[19437]: 2018-07-11 05:39:58,034 INFO  [async-dispatch-2] [o.e.j.s.h.ContextHandler] Started o.e.j.s.h.ContextHandler@4c972f0{/status,null,AVAILABLE}
Jul 11 05:39:58 el7 puppetserver[19437]: 2018-07-11 05:39:58,069 INFO  [async-dispatch-2] [p.s.m.master-service] Puppet Server has successfully started and is now ready to handle requests
Jul 11 05:39:58 el7 puppetserver[19437]: 2018-07-11 05:39:58,071 INFO  [async-dispatch-2] [p.s.l.legacy-routes-service] The legacy routing service has successfully started and is now ready to handle requests
Jul 11 05:39:58 el7 puppetserver[19437]: 2018-07-11 05:39:58,095 INFO  [async-dispatch-2] [p.s.a.analytics-service] Puppet Server Update Service has successfully started and will run in the background
Jul 11 05:39:58 el7 systemd[1]: Started puppetserver Service.
 
 
#> journalctl -t puppetserver -n 
-- Logs begin at Thu 2018-06-28 19:57:37 UTC, end at Wed 2018-07-11 05:46:26 UTC. --
Jul 11 05:39:58 el7 puppetserver[19437]: 2018-07-11 05:39:58,000 INFO  [async-dispatch-2] [p.t.s.s.status-core] Starting background monitoring of cpu usage metrics
Jul 11 05:39:58 el7 puppetserver[19437]: 2018-07-11 05:39:58,026 INFO  [async-dispatch-2] [p.t.s.s.status-service] Registering status callback function for service 'status-service', version 1.0.0
Jul 11 05:39:58 el7 puppetserver[19437]: 2018-07-11 05:39:58,026 INFO  [async-dispatch-2] [p.t.s.s.status-service] Registering status service HTTP API at /status
Jul 11 05:39:58 el7 puppetserver[19437]: 2018-07-11 05:39:58,034 INFO  [async-dispatch-2] [o.e.j.s.h.ContextHandler] Started o.e.j.s.h.ContextHandler@4c972f0{/status,null,AVAILABLE}
Jul 11 05:39:58 el7 puppetserver[19437]: 2018-07-11 05:39:58,069 INFO  [async-dispatch-2] [p.s.m.master-service] Puppet Server has successfully started and is now ready to handle requests
Jul 11 05:39:58 el7 puppetserver[19437]: 2018-07-11 05:39:58,071 INFO  [async-dispatch-2] [p.s.l.legacy-routes-service] The legacy routing service has successfully started and is now ready to handle requests
Jul 11 05:39:58 el7 puppetserver[19437]: 2018-07-11 05:39:58,095 INFO  [async-dispatch-2] [p.s.a.analytics-service] Puppet Server Update Service has successfully started and will run in the background
Jul 11 05:41:18 el7 puppetserver[19437]: 2018-07-11 05:41:18,142 WARN  [qtp1531084245-67] [puppetserver] Scope(Class[main]) Test logging
Jul 11 05:41:18 el7 puppetserver[19437]: 2018-07-11 05:41:18,160 WARN  [qtp1531084245-67] [puppetserver] Puppet Unknown variable: '::unknown_var'. (file: /etc/puppetlabs/code/environments/production/manifests/site.pp, line: 7, column: 9)
Jul 11 05:41:18 el7 puppetserver[19437]: 2018-07-11 05:41:18,201 INFO  [qtp1531084245-67] [puppetserver] Puppet Compiled catalog for el7 in environment production in 0.82 seconds

Somehow the java process behaves differently regarding stdout than the forked bash process in the background.

Comment by Thomas Mueller [ 2018/07/10 ]

can't set the ticket to a closed/invalid state. it's clearly no puppetserver issue.

Generated at Thu Nov 14 01:24:08 PST 2019 using JIRA 7.7.1#77002-sha1:e75ca93d5574d9409c0630b81c894d9065296414.