java.util.logging
package to log operations and trace
messages. This information can be particularly useful when running a
replicated JE High Availability application in order to monitor your
application's activities.
The default output lists replication node start up and shutdown operations. Initial configuration problems should show up during the startup operation. You are strongly advised to run your production application with this level of logging.
Note that an application specify java.util.logging.Handler may be specified for each environment through EnvironmentConfig.setLoggingHandler();
See the Logging section in Chapter 12, Administering Berkeley DB Java Edition Applications in the Getting Started Guide for details on logging configuration and locations.
090917 13:36:22:421 INFO [Node 1] Started ServiceDispatcher. HostPort=localhost:5500 090917 13:36:22:521 INFO [Node 1] Refreshed 0 monitors. 090917 13:36:22:529 INFO [Node 1] Current group size: 0 090917 13:36:22:530 INFO [Node 1] New node Node 1(-1) unknown to rep group 090917 13:36:22:537 INFO [Node 1] Nascent group. Node 1 is master by virtue of being the first node. 090917 13:36:22:571 INFO [Node 1] Successfully added node: Node 1(1) HostPort=localhost:5500 [ELECTABLE] 090917 13:36:22:572 INFO [Node 1] Refreshed 0 monitors. 090917 13:36:22:580 INFO [Node 1] Node Node 1 started 090917 13:36:22:593 INFO [Node 1] Feeder manager accepting requests.The master's perspective when a replica (Node 2) wants to be added, then subsequently joins and syncs up.
090917 13:36:22:676 INFO [Node 1] Feeder accepted connection from java.nio.channels.SocketChannel[connected local=/127.0.0.1:5500 remote=/127.0.0.1:59415] 090917 13:36:22:710 INFO [Node 1] Feeder-replica handshake start 090917 13:36:22:729 INFO [Node 1] Successfully added node: Node 2(2) HostPort=localhost:5501 [ELECTABLE] 090917 13:36:22:730 INFO [Node 1] Refreshed 0 monitors. 090917 13:36:22:732 INFO [Node 1] Feeder-replica Node 2 handshake completed. 090917 13:36:22:735 INFO [Node 1] Feeder-replica Node 2 syncup started. Feeder range: first=1 last=14 sync=14 txnEnd=14 090917 13:36:22:747 INFO [Node 1] Feeder-replica Node 2 start stream at VLSN: 1 090917 13:36:22:748 INFO [Node 1] Feeder-replica Node 2 syncup ended. Elapsed time: 13ms 090917 13:36:22:750 INFO [Node 1] Feeder output thread for replica Node 2 started at VLSN: 1 Master at: 14 VLSN delta: 13 Socket: (Node 2(2))java.nio.channels.SocketChannel[connected local=/127.0.0.1:5500 remote=/127.0.0.1:59415]A replica (Node 5) comes up. We can tell who the master (Node 1) is:
090917 13:36:23:179 INFO [Node 5] Started ServiceDispatcher. HostPort=localhost:5504 090917 13:36:23:181 INFO [Node 5] Refreshed 0 monitors. 090917 13:36:23:182 INFO [Node 5] Current group size: 0 090917 13:36:23:182 INFO [Node 5] New node Node 5(-1) unknown to rep group 090917 13:36:23:186 INFO [Node 5] New node Node 5 located master: Node 1(1) 090917 13:36:23:188 INFO [Node 5] Node Node 5 started 090917 13:36:23:188 INFO [Node 5] Replica loop started with master: Node 1(1) 090917 13:36:23:192 INFO [Node 5] Replica-feeder handshake start 090917 13:36:23:274 INFO [Node 5] Replica-feeder Node 1 handshake completed. 090917 13:36:23:274 INFO [Node 5] Replica-feeder Node 1 syncup started. Replica range: first=-1 last=-1 sync=-1 txnEnd=-1 090917 13:36:23:275 INFO [Node 5] Replica-feeder Node 1 start stream at VLSN: 1 090917 13:36:23:276 INFO [Node 5] Replica-feeder Node 1 syncup ended. Elapsed time: 2ms 090917 13:36:23:280 INFO [Node 5] Replica initialization completed. Replica VLSN: -1 Heartbeat master commit VLSN: 29 VLSN delta: 30A master node (node 1) is shutting down and is closing connections to its replicas. (Nodes 2, 3, 4, 5)
090917 13:36:39:502 INFO [Node 1] Shutting down node Node 1(1) 090917 13:36:39:502 INFO [Node 1] Elections shutdown initiated 090917 13:36:39:504 INFO [Node 1] Elections shutdown completed 090917 13:36:39:504 INFO [Node 1] Feeder manager soft shutdown. 090917 13:36:39:505 INFO [Node 1] Shutting down feeder for replica Node 4 write time: 214ms Avg write time: 19us 090917 13:36:40:502 INFO [Node 1] Feeder output for replica Node 4 shutdown. feeder VLSN: 11,126 currentCommitVLSN: 11,025 090917 13:36:40:503 INFO [Node 1] Thread[Feeder Output for Node 4,5,] has exited. 090917 13:36:40:503 INFO [Node 1] Thread[Feeder Input for Node 4,5,] has exited. 090917 13:36:40:504 INFO [Node 1] Shutting down feeder for replica Node 2 write time: 212ms Avg write time: 19us 090917 13:36:41:503 INFO [Node 1] Feeder output for replica Node 2 shutdown. feeder VLSN: 11,126 currentCommitVLSN: 11,025 090917 13:36:41:504 INFO [Node 1] Thread[Feeder Output for Node 2,5,] has exited. 090917 13:36:41:504 INFO [Node 1] Thread[Feeder Input for Node 2,5,] has exited. 090917 13:36:41:504 INFO [Node 1] Shutting down feeder for replica Node 3 write time: 230ms Avg write time: 20us 090917 13:36:42:504 INFO [Node 1] Feeder output for replica Node 3 shutdown. feeder VLSN: 11,126 currentCommitVLSN: 11,025 090917 13:36:42:504 INFO [Node 1] Thread[Feeder Output for Node 3,5,] has exited. 090917 13:36:42:505 INFO [Node 1] Thread[Feeder Input for Node 3,5,] has exited. 090917 13:36:42:505 INFO [Node 1] Shutting down feeder for replica Node 5 write time: 219ms Avg write time: 19us 090917 13:36:43:502 INFO [Node 1] Feeder output for replica Node 5 shutdown. feeder VLSN: 11,126 currentCommitVLSN: 11,025 090917 13:36:43:503 INFO [Node 1] Thread[Feeder Output for Node 5,5,] has exited. 090917 13:36:43:503 INFO [Node 1] Thread[Feeder Input for Node 5,5,] has exited. 090917 13:36:43:503 INFO [Node 1] Feeder manager exited. CurrentCommit VLSN: 11,025 090917 13:36:43:503 INFO [Node 1] RepNode main thread shutting down. 090917 13:36:43:504 INFO [Node 1] RepNode main thread: DETACHED Node 1(1) exited. 090917 13:36:43:504 INFO [Node 1] ServiceDispatcher shutdown starting. HostPort=localhost:5500 Registered services: [] 090917 13:36:43:505 INFO [Node 1] ServiceDispatcher shutdown completed. HostPort=localhost:5500 090917 13:36:43:505 INFO [Node 1] Node 1(1) shutdown completed.