Logging in Java libraries for Firebase and Google Cloud Platform
When developing server-side Firebase applications using the Firebase Admin SDK for Java, it is sometimes useful to look at the debug logs produced by the SDK. The FirebaseDatabase class provides a setLogLevel() method that facilitates this to a certain extent. However, setLogLevel() method was deprecated in the version 5.3.0 release of the Admin Java SDK. The new recommended approach for obtaining debug logs from the SDK is via SLF4J. This change comes with several advantages that enterprise Java developers would find useful.
- It is now possible to configure logging independent of the application code. Enabling debug logs no longer requires code changes.
- SLF4J, being a high-level facade, supports a number of logging frameworks. We can log to the console, Log4J, Logback or any other logging framework compatible with SLF4J.
- A wide range of options to configure logging levels (debug, info, warn etc.), patterns, rotation schedules and more.
A brief introduction to logging facades and SLF4J
Logging in enterprise applications is a complicated matter. There are many aspects to consider including persistence, log rotation, formatting and performance. Fortunately, there are many powerful logging frameworks such as Logback, Apache Log4J, and Java’s built-in java.util.logging (JUL) that take care of most of these concerns. However, each of these frameworks have a slightly different API and a configuration model. Therefore if you write an application using any one framework, you will be tied to that framework. This is particularly problematic for library developers, since the users of the library may want to use different logging frameworks.
This is where the logging facades come in. A logging facade is a high-level logging API that acts as a mediator between application/library code, and the logging frameworks. We write our code using a logging facade, instead of a specific logging framework. Then at the deployment time we can decide what concrete logging framework to use (i.e. late binding the logging framework). By decoupling code from concrete logging frameworks, facades yield greater levels of code portability and maintainability.
SLF4J is one such logging facade. It supports all the common logging frameworks, and is favored by many Java developers due to its simple API and the performant implementation. Starting from version 5.3.0, Firebase Admin SDK for Java uses SLF4J as its logging facade. This enables developers using the Admin Java SDK to use any concrete logging framework of their choice. SLF4J can be easily wired up to a logging framework by dropping a binding library to the classpath. It has been tested in many environments, and also works well in Google App Engine.
Printing Firebase debug logs to the console
This is mainly useful when testing or debugging an application locally. Simply add the slf4j-simple binding to the application classpath, and set the -Dorg.slf4j.simpleLogger.defaultLogLevel=debug system property. The Admin Java SDK will start printing debug log statements to your console:
[FirebaseDatabaseWorker] DEBUG com.google.firebase.database.connection.PersistentConnection - pc_0 - Scheduling connection attempt[FirebaseDatabaseWorker] DEBUG com.google.firebase.database.connection.util.RetryHelper - Scheduling retry in 0ms[FirebaseDatabaseWorker] DEBUG com.google.firebase.database.connection.PersistentConnection - pc_0 - Trying to fetch auth token[FirebaseDatabaseWorker] DEBUG com.google.firebase.database.connection.PersistentConnection - pc_0 - Successfully fetched token, opening connection[FirebaseDatabaseWorker] DEBUG io.netty.util.internal.logging.InternalLoggerFactory - Using SLF4J as the default logging framework[FirebaseDatabaseWorker] DEBUG io.netty.util.internal.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024[FirebaseDatabaseWorker] DEBUG io.netty.util.internal.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096[FirebaseDatabaseWorker] DEBUG io.netty.util.internal.PlatformDependent0 - Java version: 8[firebase-websocket-worker] DEBUG com.google.firebase.database.connection.WebsocketConnection - ws_0 - websocket opened[FirebaseDatabaseWorker] DEBUG com.google.firebase.database.connection.WebsocketConnection - ws_0 - Reset keepAlive[firebase-websocket-worker] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder - Decoding WebSocket Frame opCode=1[firebase-websocket-worker] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder - Decoding WebSocket Frame length=132[firebase-websocket-worker] DEBUG com.google.firebase.database.connection.WebsocketConnection - ws_0 - ws message: {"t":"c","d":{"t":"h","d":{"ts":1517693580787,"v":"5","h":"s-usc1c-nss-214.firebaseio.com","s":"nPyuogc4ji6AURBD8pKEUPzdBsOedoCP"}}}[FirebaseDatabaseWorker] DEBUG com.google.firebase.database.connection.WebsocketConnection - ws_0 - Reset keepAlive. Remaining: 44998[FirebaseDatabaseWorker] DEBUG com.google.firebase.database.connection.WebsocketConnection - ws_0 - HandleNewFrameCount: 1
Take a look at the API docs of the SimpleLogger for additional options you can set to further configure the log output. Instead of setting them as individual system properties, you can also save them to a file named simplelogger.properties, and put it in your application classpath to be auto discovered.
The deprecated setLogLevel() method also prints logs to the console. Therefore, the approach described here can be used as an alternative to calling setLogLevel(Level.DEBUG) in your application code.
Collecting logs from other Google Cloud Platform libraries
Most Google Cloud Platform (GCP) libraries for Java do not use a logging facade yet, and instead directly log to the JUL framework. Personally I’m not a fan of JUL, but one cannot ignore the appeal of an API that is built into the language. You can configure how JUL operates by creating a logging.properties file for your app. Just remember to set the -Djava.util.logging.config.file system property to point to that file when executing the application. If you are not familiar with logging.properties files, listing 1 shows an example.
Configuration in listing 1 instructs JUL to log to the console. It enables debug logging for com.google.* packages, which includes all GCP libraries. Then it sets a pattern for the log statements. Some sample JUL logs captured using listing 1 are shown below. These logs were produced by the Google API client library — a dependency used by the Admin SDK to make HTTP calls. This specific interaction was triggered by a call to the FirebaseAuth.getUser() API in the Admin SDK:
2018-02-03 14:01:31 CONFIG com.google.api.client.http.HttpRequest execute -------------- REQUEST --------------
POST https://www.googleapis.com/identitytoolkit/v3/relyingparty/getAccountInfo
Accept-Encoding: gzip
Authorization: <Not Logged>
User-Agent: Google-HTTP-Java-Client/1.23.0 (gzip)
x-client-version: Java/Admin/5.8.0
Content-Type: application/json; charset=UTF-8
Content-Length: 192018-02-03 14:01:31 CONFIG com.google.api.client.http.HttpRequest execute curl -v --compressed -X POST -H 'Accept-Encoding: gzip' -H 'Authorization: <Not Logged>' -H 'User-Agent: Google-HTTP-Java-Client/1.23.0 (gzip)' -H 'x-client-version: Java/Admin/5.8.0' -H 'Content-Type: application/json; charset=UTF-8' -d '@-' -- 'https://www.googleapis.com/identitytoolkit/v3/relyingparty/getAccountInfo' << $$$
2018-02-03 14:01:31 CONFIG com.google.api.client.util.LoggingByteArrayOutputStream close Total: 19 bytes
2018-02-03 14:01:31 CONFIG com.google.api.client.util.LoggingByteArrayOutputStream close {"localId":["uid"]}
2018-02-03 14:01:31 CONFIG com.google.api.client.http.HttpResponse <init> -------------- RESPONSE --------------
HTTP/1.1 200 OK
Transfer-Encoding: chunked
Alt-Svc: hq=":443"; ma=2592000; quic=51303431; quic=51303339; quic=51303338; quic=51303337; quic=51303335,quic=":443"; ma=2592000; v="41,39,38,37,35"
Server: GSE
X-Content-Type-Options: nosniff
Pragma: no-cache
Date: Sat, 03 Feb 2018 22:01:31 GMT
X-Frame-Options: SAMEORIGIN
Cache-Control: no-cache, no-store, max-age=0, must-revalidate
ETag: "MXZTd1FuXGy6b-RgGu8L_ikGax4/vyGp6PvFo4RvsFtPoIWeCReyIC8"
Content-Encoding: gzip
Vary: X-Origin
Vary: Origin
Expires: Mon, 01 Jan 1990 00:00:00 GMT
X-XSS-Protection: 1; mode=block
Content-Type: application/json; charset=UTF-82018-02-03 14:01:31 CONFIG com.google.api.client.util.LoggingByteArrayOutputStream close Total: 54 bytes
2018-02-03 14:01:31 CONFIG com.google.api.client.util.LoggingByteArrayOutputStream close {
"kind": "identitytoolkit#GetAccountInfoResponse"
}
If you wish to also direct the Firebase Admin SDK logs to JUL, you just need to drop the slf4j-jdk14 binding to the application classpath. Here are some Realtime Database logs captured in this manner:
2018-02-03 14:01:31 FINE com.google.firebase.internal.RevivingScheduledExecutor$1 newThread Creating new thread for: FirebaseDatabaseWorker
2018-02-03 14:01:31 FINE com.google.firebase.database.logging.LogWrapper debug pc_0 - Scheduling connection attempt
2018-02-03 14:01:31 FINE com.google.firebase.database.logging.LogWrapper debug Scheduling retry in 0ms
2018-02-03 14:01:31 FINE com.google.firebase.database.logging.LogWrapper debug pc_0 - Trying to fetch auth token
2018-02-03 14:01:31 FINE com.google.firebase.database.logging.LogWrapper debug pc_0 - Successfully fetched token, opening connection
2018-02-03 14:01:31 FINE com.google.firebase.database.logging.LogWrapper debug conn_0 - Opening a connection
2018-02-03 14:01:32 FINE com.google.firebase.internal.RevivingScheduledExecutor$1 newThread Creating new thread for: firebase-websocket-worker
2018-02-03 14:01:32 FINE com.google.firebase.database.logging.LogWrapper debug ws_0 - websocket opened
2018-02-03 14:01:32 FINE com.google.firebase.database.logging.LogWrapper debug ws_0 - Reset keepAlive
2018-02-03 14:01:32 FINE com.google.firebase.database.logging.LogWrapper debug ws_0 - ws message: {"t":"c","d":{"t":"h","d":{"ts":1517695292399,"v":"5","h":"s-usc1c-nss-214.firebaseio.com","s":"TOY9NrzcsYiZ0S0b4oHYVZdaeuMCLQkf"}}}
2018-02-03 14:01:32 FINE com.google.firebase.database.logging.LogWrapper debug ws_0 - Reset keepAlive. Remaining: 44998
2018-02-03 14:01:32 FINE com.google.firebase.database.logging.LogWrapper debug ws_0 - HandleNewFrameCount: 1Since listing 1 enables debug logging for all com.google.* packages, it activates the debug mode for Firebase Admin SDK as well, which uses com.google.firebase as its package name.
Logging in the Google App Engine environment
Google App Engine (GAE) expects applications and libraries to log to the JUL framework. You can configure logging by creating a logging.properties file in the WEB-INF/ directory of your app. Listing 2 shows a configuration that enables debug logs for the Firebase Admin SDK.
You also need to reference the configuration file in your appengine-web.xml, as illustrated in listing 3.
Finally, to actually direct Admin SDK logs to JUL, bundle the slf4j-jdk14 binding with your app (i.e. make sure it goes in the WEB-INF/lib directory of the app). Now when you deploy the app in the cloud, GAE will capture the debug logs produced by the Admin SDK, and make them accessible through the GCP web console.
Conclusion
Logging is an important aspect in enterprise Java applications that often comes in handy when testing or debugging code. GCP libraries log to Java’s built-in JUL framework, which can be configured via a logging.properties file. Firebase Admin SDK for Java goes one step further by using SLF4J as a logging facade, which enables developers to use any logging framework of their choice (including JUL). Logs produced by these libraries can be directed to the console, the file system or any other persistent storage suitable for logs. When deployed in the App Engine environment, the logs are automatically collected, parsed and sent to the GCP console for presentation.
I hope this answers most of the questions Java developers may have on obtaining logs from server-side Firebase and GCP libraries. If you have come across any interesting logging-related use cases, feel free to share them. Happy coding with Firebase and Google Cloud Platform!