Debugging

Live Execution

Dumping Values

curl --data '<% println(application.globals.get("db.connection")) %>' http://localhost:8080/myapp/execute/

curl --data '<% application.logger.info(application.globals.get("db.connection")) %>' http://localhost:8080/myapp/execute/

Scheduling Background Tasks

<%
document.require('/prudence/tasks/')
Prudence.Tasks.task({
	fn: function() {
		application.logger.info(application.globals.get('db.connection'))
	},
	repeatEvery: '5s'
})
%>

curl --data-binary @program.js http://localhost:8080/myapp/execute/

Debug Page

curl --data '<% throw null %>' http://localhost:8080/myapp/execute/

Logging

• "common.log": The rolling log file shared by all applications and libraries. If they don't specify their own, it will default to this (it's configured as attached to the root logger.)
• "application-[name].log": A rolling log file per Prudence application, where "[name]" is the application's subdirectory name.
• "web.log": A rolling log file of all incoming HTTP requests in NCSA-style.
• "service-prudence.log": This will be available if you're running Prudence as a service. Note that it is configured separately, and does not in fact use JVM logging.

Introduction

API

• severe (1000): These are very important messages, usually about errors or other problems. You'd likely want all loggers to include this level. You should use this level sparingly.
• warning (900): These are important, but not crucial. Usually used for temporary errors or for problems that do not cause failure.
• config (800): These express change of state (configuration), and as such probably don't happen that often. They most likely appear during the initial bootstrapping, but can happen while the application runs if something causes a subsystem to restart or reconfigure itself.
• info (700): These informational messages are used for keeping track of the application's runtime health: they don't specify a problem or a change, only report normal activity. This is the most commonly used message.
• fine (500): This and the following two levels should be reserved for debugging: you normally won't go beyond "info" unless you're specifically trying to debug a problem, as this would cause a lot of chatter in your logs.
• finer (400): More minute debugging.
• finest (300): Most minute debugging.

application.logger.info('An info-level message')
application.logger.warning('Something bad happened!')

application.getSubLogger('email').info('An info-level message')

importClass(java.util.logging.Logger)
var logger = Logger.getLogger('myApp.system.mail')
logger.info('My logger!')

document.require('/prudence/logging/')
var logger = new Prudence.Logging.Logger()
logger.log('info', 'An informational message')
logger.fine('A fine message')
logger.warning('A warning')
new Prudence.Logging.Logger('email').info('Hello from the Email subsystem')

logger.severe('Hi, {0} and {1}!', 'mom', 'dad')
logger.info('Hi, {name}!', {name: 'mom'})
logger.finest('Hi, {name}!', function(original, key) {
	if (key == 'name') {
		return 'mom'
	}
	return null
})

var x = {test: 'hello', more: [1, 2, 3]}
logger.dumpShort(x, 'Our object in short form')
logger.dumpLong(x, 'Our object in long form')
logger.dump(x, 'This is an alias for dumpShort')

try {
	nothing()
}
catch (e) {
	logger.exception(e)
}

logger.time('The loop', function() {
	var x = 1
	for (var i = 0; i < 100000; i++) {
		x /= 2
	}
})

if (logger.isLoggable(java.util.logging.Level.FINE)) {
	var data = heavyFetchFromDatabase()
	return 'This function was called because the "fine" log level is permitted'
}

logger.fine(function() {
	var data = heavyFetchFromDatabase()
	return 'This function was called because the "fine" log level is permitted'
})

Configuration

Unfortunately, until the JVM finally included a logging standard, there were already other popular logging APIs. Also unfortunately, the introduced standard is simply not as powerful as Log4j, and we did not want to compromise on power. Fortunately, the SLF4J library allows Sincerity to mimic all these various APIs while implementing them in Log4j, so you get the best of all worlds as well as a uniform system.

• Restlet logs its internal application events to "org.restlet.Application.[name]". You can access this logger in your code using the application.application.logger API. By default, it is attached to the application's appender and set to level "warn".
• Jetty and Hazelcast both feature robust event logging.

Quick-and-Dirty Logging to the Console

java.lang.System.out.println('Desperate times call for desperate measures!')

JVM Logging

handlers = java.util.logging.FileHandler, java.util.logging.ConsoleHandler
java.util.logging.FileHandler.pattern = log.%u.%g.txt
java.util.logging.FileHandler.formatter = java.util.logging.SimpleFormatter
java.util.logging.SimpleFormatter.format=%1$tb %1$td, %1$tY %1$tl:%1$tM:%1$tS %1$Tp %2$s %4$s: %5$s%n
java.util.logging.ConsoleHandler.level = ALL
com.threecrickets.prudence.cache.level = ALL
.level = INFO

JVM_SWITCHES=-Djava.util.logging.config.file=logging.properties sincerity use mycontainer : start prudence

Best Practices

• Remember that people read the logs! This can mean other developers in your team, but it can also be you in the future, at a time when you may forget why you added a particular log message. Because of this, you always want every log message to be clear in and of itself. For example, if you're dumping the contents of a variable, prefix it with the name of the variable, as well as the name of the function or file from which it is logged. Otherwise, it would be impossible for others to find out where the dump is coming from and how to disable it.
• Use log levels wisely: if you're adding a logging message purely for debugging, don't set it to "info", otherwise it will remain as distracting chatter during normal operations. Use "fine" instead.
• Some log messages are very specific, and added during debugging, but would be distracting once the bug is solved. In that case make sure to disable the message when you're dong debugging by either switching it to the "finest" level, commenting out the code, or just deleting it. Make sure not to commit code that outputs distracting log messages.
• A good, clear log is an invaluable debugging tool. A confusing, messy log is worthless!

Debug Page

• Error stack trace, with links to the source code
• HTTP request warnings
• HTTP request information, including all headers parsed and organized:
  • URIs
  • Query params
  • Media preferences for content negotiation
  • Conditions for content negotiation
  • Caching directives
  • Client identification
  • Cookies
  • Payload
• conversations.locals
• HTTP response attributes
• Application information:
  • application.globals
  • application.sharedGlobals
  • executable.globals
• Scripturian:
  • Executable attributes
  • Execution context attributes
• Low-level JVM stack trace

Monitoring

Threads

• qtp: Jetty server's selectors and acceptors
• HttpClient: Jetty client
• cron4j: cron4j
• hz: Hazelcast
• Wrapper: The Sincerity service plugin wrapper
• JXM and RMI: These are used by JMX itself

Management Beans

• java.lang: General JVM tools, such as operating system information as well as class loader, memory, compilation and threading statistics; use the "gc" operation in the "Memory" type to cause immediate garbage collection
• java.nio: Some useful I/O statistics
• java.util.logging: Allows you to query the JULI API
• org.apache.logging.log4j2: Available when you are using the Sincerity logging plugin; access to the logging implementation; note that you can also install a dedicated GUI using the JConsole plugin: see the Log4j management documentation for more information
• org.tanukisoftware.wrapper: Available when you are using the Sincerity service plugin; operations allows you to stop/restart the service

Remote JMX

Memory Leaks

jmap -dump:live,format=b,file=/full/path/to/dumps/prudence.bin <pid>

• In Linux, you might need to enable inter-process access for ptrace:

  echo 0 | sudo tee /proc/sys/kernel/yama/ptrace_scope
  

• Try using root access to run jmap
• Try adding the "-F" switch (though it will likely only create a partial dump)

jhat -J-mx2000m prudence.bin

JVM_SWITCHES=\
	-XX:+HeapDumpOnOutOfMemoryError \
	-XX:HeapDumpPath=/full/path/to/logs/ \
	sincerity start prudence

JVM_SWITCHES=\
	-Xloggc:/full/path/to/logs/gc.log \
	-XX:+PrintGCDetails \
	-XX:+PrintTenuringDistribution \
	sincerity start prudence

# Out-of-memory heap dumps
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath={sincerity.container.root}/logs/
​
# Garbage collection log
-Xloggc:{sincerity.container.root}/logs/gc.log
-XX:+PrintGCDetails
-XX:+PrintTenuringDistribution

The Prudence Manual is provided for you under the terms of the Creative Commons Attribution-NonCommercial-ShareAlike 4.0 International License. The complete manual is available for download as a PDF.