Logging format not honored

[ameissnersofi]

Hi! I seem to be having issues with the logging format not being used when the job logs are streamed to stdout. The pattern is what's on the readme:

log4j.appender.executionevents.layout.ConversionPattern=%d{ISO8601} project: %X{project} execution: %X{execid} (%X{event}, %X{nodename}) %X{group}/%X{name} [%X{id}] - %m%n

(as well as everything else - I followed the readme to a T.)

The result is of my test job in stdout is:

2016-10-19 12:18:00,162 INFO  stream - START
2016-10-19 12:18:00,171 INFO  stream - localhost
2016-10-19 12:18:00,282 INFO  stream - Test
2016-10-19 12:18:00,587 INFO  stream - END

My project name is "Test", job name is "test" and the only step is "echo Test". It doesn't look like the project name, job name, execid, etcd... are getting logged. Any insight would be immensely appreciated! Thanks so much!

[gschueler]

what is your whole log4j config file?

[ameissnersofi]

It's just what's out of the box in rundeck with the readme's stuff appended to it.

${RDECK_BASE}/server/exp/webapp/WEB-INF/classes/log4j.properties

log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{ISO8601} %-5p %c{1} - %m%n
# Enable logging for everything. Rarely useful
log4j.rootLogger=warn, stdout, file

# Enable audit logging
log4j.logger.com.dtolabs.rundeck.core.authorization=info, audit
log4j.additivity.com.dtolabs.rundeck.core.authorization=false

# Enable options remote URL logging
log4j.logger.com.dtolabs.rundeck.remoteservice.http.options=INFO, options
log4j.additivity.com.dtolabs.rundeck.remoteservice.http.options=false

# Enable Job changes logging
log4j.logger.com.dtolabs.rundeck.data.jobs.changes=INFO, jobchanges
log4j.additivity.com.dtolabs.rundeck.data.jobs.changes=false

# Enable Execution event logging
log4j.logger.org.rundeck.execution.status=INFO, execevents
log4j.additivity.org.rundeck.execution.status=false

# Enable API request logging
log4j.logger.org.rundeck.api.requests=INFO,apirequests
log4j.additivity.org.rundeck.api.requests=false

# Enable Web access logging
log4j.logger.org.rundeck.web.requests=INFO,access
log4j.additivity.org.rundeck.web.requests=false

# Enable Storage logging
log4j.logger.org.rundeck.storage.events=INFO,storage
log4j.additivity.org.rundeck.storage.events=false

# Enable Project manager logging
log4j.logger.grails.app.services.rundeck.services.ProjectManagerService=INFO,stdout
log4j.additivity.grails.app.services.rundeck.services.ProjectManagerService=false

# Enable this logger to log Hibernate output
# handy to see its database interaction activity
#log4j.logger.org.hibernate=debug,stdout
#log4j.additivity.org.hibernate=false

# Enable this logger to see what Spring does, occasionally useful
#log4j.logger.org.springframework=info,stdout 
#log4j.additivity.org.springframework=false

# This logger covers all of Grails' internals
# Enable to see whats going on underneath. 
log4j.logger.org.codehaus.groovy.grails=warn,stdout
log4j.additivity.org.codehaus.groovy.grails=false

# This logger is useful if you just want to see what Grails
# configures with Spring at runtime. Setting to debug will show
# each bean that is configured
log4j.logger.org.codehaus.groovy.grails.commons.spring=warn,stdout
log4j.additivity.org.codehaus.groovy.grails.commons.spring=false  

# Interesting Logger to see what some of the Grails factory beans are doing
log4j.logger.org.codehaus.groovy.grails.beans.factory=warn,stdout
log4j.additivity.org.codehaus.groovy.grails.beans.factory=false

# This logger is for Grails' public APIs within the grails. package
log4j.logger.grails=warn,stdout
log4j.additivity.grails=false        

#
# file - DailyRollingFileAppender
#
log4j.appender.file=org.apache.log4j.DailyRollingFileAppender
log4j.appender.file.file=/Users/ameissner/Desktop/rundeck/server/logs${file.separator}rundeck.log
log4j.appender.file.datePattern='.'yyyy-MM-dd
log4j.appender.file.append=true
log4j.appender.file.layout=org.apache.log4j.PatternLayout
log4j.appender.file.layout.ConversionPattern=%d{ISO8601} [%t] %-5p %c - %m%n

#log4j.logger.org.codehaus.groovy.grails.plugins.quartz=debug,stdout
#log4j.additivity.org.codehaus.groovy.grails.plugins.quartz=false

#
# audit 
#
log4j.appender.audit=org.apache.log4j.DailyRollingFileAppender
log4j.appender.audit.file=/Users/ameissner/Desktop/rundeck/server/logs${file.separator}rundeck.audit.log
log4j.appender.audit.append=true
log4j.appender.audit.layout=org.apache.log4j.PatternLayout
log4j.appender.audit.layout.ConversionPattern=%d{ISO8601} - %m%n

#
# options log
#
# Logs remote HTTP requests for Options JSON data
#
log4j.appender.options=org.apache.log4j.DailyRollingFileAppender
log4j.appender.options.file=/Users/ameissner/Desktop/rundeck/server/logs/rundeck.options.log
log4j.appender.options.append=true
log4j.appender.options.layout=org.apache.log4j.PatternLayout
log4j.appender.options.layout.ConversionPattern=[%d{ISO8601}] %X{httpStatusCode} %X{contentLength}B %X{durationTime}ms %X{lastModifiedDateTime} [%X{jobName}] %X{url} %X{contentSHA1}%n

#
# storage log
#
# Logs events for Rundeck storage layer
#
log4j.appender.storage=org.apache.log4j.DailyRollingFileAppender
log4j.appender.storage.file=/Users/ameissner/Desktop/rundeck/server/logs/rundeck.storage.log
log4j.appender.storage.append=true
log4j.appender.storage.layout=org.apache.log4j.PatternLayout
log4j.appender.storage.layout.ConversionPattern=[%d{ISO8601}] %X{action} %X{type} %X{path} %X{status} %X{metadata}%n

#
# job changes log
#
# Logs all Job definition changes
#
log4j.appender.jobchanges=org.apache.log4j.DailyRollingFileAppender
log4j.appender.jobchanges.file=/Users/ameissner/Desktop/rundeck/server/logs/rundeck.jobs.log
log4j.appender.jobchanges.append=true
log4j.appender.jobchanges.layout=org.apache.log4j.PatternLayout
log4j.appender.jobchanges.layout.ConversionPattern=[%d{ISO8601}] %X{user} %X{change} [%X{id}] %X{project} "%X{groupPath}/%X{jobName}" (%X{method})%X{extraInfo}%n

#
# executions log
#
# Logs all execution events (start,finish,delete)
#
log4j.appender.execevents=org.apache.log4j.DailyRollingFileAppender
log4j.appender.execevents.file=/Users/ameissner/Desktop/rundeck/server/logs/rundeck.executions.log
log4j.appender.execevents.append=true
log4j.appender.execevents.layout=org.apache.log4j.PatternLayout
log4j.appender.execevents.layout.ConversionPattern=[%d{ISO8601}] %X{eventUser} %X{event} [%X{id}:%X{state}] %X{project} %X{user}/%X{abortedby} "%X{groupPath}/%X{jobName}"[%X{uuid}] %n

#
# api request log
#
# Logs all API requests
#
log4j.appender.apirequests=org.apache.log4j.DailyRollingFileAppender
log4j.appender.apirequests.file=/Users/ameissner/Desktop/rundeck/server/logs/rundeck.api.log
log4j.appender.apirequests.append=true
log4j.appender.apirequests.layout=org.apache.log4j.PatternLayout
log4j.appender.apirequests.layout.ConversionPattern=[%d{ISO8601}] %X{remoteHost} %X{secure} %X{remoteUser} %X{authToken} %X{duration} %X{project} "%X{method} %X{uri}" (%X{userAgent})%n

#
# Web access log
#
# Logs all Web requests
#
log4j.appender.access=org.apache.log4j.DailyRollingFileAppender
log4j.appender.access.file=/Users/ameissner/Desktop/rundeck/server/logs/rundeck.access.log
log4j.appender.access.append=true
log4j.appender.access.layout=org.apache.log4j.PatternLayout
log4j.appender.access.layout.ConversionPattern=[%d{ISO8601}] "%X{method} %X{uri}" %X{remoteHost} %X{secure} %X{remoteUser} %X{authToken} %X{duration} %X{project} [%X{contentType}] (%X{userAgent})%n

#
# Disable h2database logging
# workaround for issue https://github.com/rundeck/rundeck/issues/1175
log4j.logger.h2database = off

# rundeck-log4j-streaming-log-plugin
log4j.logger.org.rundeck.log.event.stream=info,executionevents,stdout
log4j.additivity.org.rundeck.log.event.stream=false

log4j.appender.executionevents=org.apache.log4j.DailyRollingFileAppender
log4j.appender.executionevents.file=/var/log/rundeck/rundeck.executionevents.log
log4j.appender.executionevents.append=true
log4j.appender.executionevents.layout=org.apache.log4j.PatternLayout
log4j.appender.executionevents.layout.ConversionPattern=%d{ISO8601} project: %X{project} execution: %X{execid} (%X{event}, %X{nodename}) %X{group}/%X{name} [%X{id}] - %m%n

[ameissnersofi]

Here's $RDECK_BASE/server/logs/rundeck.executionevents.log (after noticing i was logging to /var/log/rundeck/rundeck.executionevents.log) :(

2016-10-19 12:52:51,803 project: Test execution: 1 (start, ) /testj [5c2bb986-4179-4812-937b-5a0ba7b39578] - START
2016-10-19 12:52:52,139 project: Test execution: 1 (node, localhost) /testj [5c2bb986-4179-4812-937b-5a0ba7b39578] - localhost
2016-10-19 12:52:52,209 project: Test execution: 1 (log, ) /testj [5c2bb986-4179-4812-937b-5a0ba7b39578] - hello world
2016-10-19 12:52:52,670 project: Test execution: 1 (end, ) /testj [5c2bb986-4179-4812-937b-5a0ba7b39578] - END

so... my bad. :( The logging format is doing the right thing - just not in the place I thought it would. Sorry for my confusion.