Erratic snapshot behavior

8 views
Skip to first unread message

jagwire

unread,
May 16, 2011, 1:51:19 PM5/16/11
to Open Wonderland Forum
Hello,

We've been seeing strange behavior from the darkstar server as of
late. After extended amounts of placing models in world, we will try
to create a snapshot, and the darkstar server will fail to restart,
the snapshot and darkstar logs show the following exception:


[java] May 16, 2011 12:31:42 PM com.sun.sgs.impl.kernel.Kernel
loadProfileListeners
[java] WARNING: Failed to load ProfileListener
com.sun.sgs.impl.profile.listener.AggregateProfileListener ... it will
not be available for profiling
[java] java.net.BindException: Address already in use
[java] at java.net.PlainSocketImpl.socketBind(Native Method)
[java] at java.net.PlainSocketImpl.bind(PlainSocketImpl.java:
365)
[java] at java.net.ServerSocket.bind(ServerSocket.java:328)
[java] at java.net.ServerSocket.<init>(ServerSocket.java:194)
[java] at java.net.ServerSocket.<init>(ServerSocket.java:106)
[java] at
com.sun.sgs.impl.profile.util.NetworkReporter.<init>(NetworkReporter.java:
57)
[java] at
com.sun.sgs.impl.profile.listener.AggregateProfileListener.<init>(AggregateProfileListener.java:
128)
[java] at
sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
[java] at
sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:
39)
[java] at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:
27)
[java] at
java.lang.reflect.Constructor.newInstance(Constructor.java:513)
[java] at
com.sun.sgs.impl.profile.ProfileCollectorImpl.addListener(ProfileCollectorImpl.java:
324)
[java] at
com.sun.sgs.impl.kernel.Kernel.loadProfileListeners(Kernel.java:375)
[java] at com.sun.sgs.impl.kernel.Kernel.<init>(Kernel.java:
345)
[java] at com.sun.sgs.impl.kernel.Kernel.main(Kernel.java:
1147)


The solution is to kill -9 any processes on the server mentioning
darkstar and then restart from the web administration page. Are there
any suggested strategies for narrowing down why the first darkstar
process doesn't release the socket binding upon snapshot creation? We
really only ever see this after extended periods of time placing
models in-world. Though tedious when we try to reproduce it.

thanks!
jW

jagwire

unread,
May 20, 2011, 2:11:38 PM5/20/11
to Open Wonderland Forum
maybe a bug in webDAV?

bump.

Jonathan Kaplan

unread,
May 20, 2011, 2:15:13 PM5/20/11
to openwon...@googlegroups.com
In the ~/.wonderland-server/0.5-dev/logs directory, there should be a "darkstar-server-snapshot.log". That is the server log taken during the snapshot operation. I'll guess that there are a bunch of exceptions in that log. What are the first few?

It sounds like what is going on is that the server is never able to properly take the snapshot and is never shutting down. When the server is restarted later, there is a second copy running.

jagwire

unread,
May 20, 2011, 2:23:22 PM5/20/11
to Open Wonderland Forum
There are several of the following exceptions:

[java] FINE: createSpatialCell 47 dsID 983
[java] May 20, 2011 12:37:00 PM
org.jdesktop.wonderland.server.spatial.UniverseService
$ChangeApplication run
[java] WARNING: [UniverseService] Unexpected error in change
thread
[java] java.lang.NullPointerException
[java] at
org.jdesktop.wonderland.server.spatial.impl.SpatialCellImpl.setRoot(SpatialCellImpl.java:
441)
[java] at
org.jdesktop.wonderland.server.spatial.impl.SpatialCellImpl.setParent(SpatialCellImpl.java:
454)
[java] at
org.jdesktop.wonderland.server.spatial.impl.SpatialCellImpl.addChild(SpatialCellImpl.java:
176)
[java] at
org.jdesktop.wonderland.server.spatial.UniverseService
$7.run(UniverseService.java:341)
[java] at
org.jdesktop.wonderland.server.spatial.UniverseService
$ChangeApplication.run(UniverseService.java:933)
[java] May 20, 2011 12:37:00 PM
org.jdesktop.wonderland.server.spatial.impl.UniverseImpl
createSpatialCell
[java] FINE: createSpatialCell 48 dsID 990
[java] May 20, 2011 12:37:00 PM
org.jdesktop.wonderland.server.spatial.UniverseService
$ChangeApplication run
[java] WARNING: [UniverseService] Unexpected error in change
thread
[java] java.lang.NullPointerException
[java] at
org.jdesktop.wonderland.server.spatial.impl.SpatialCellImpl.setRoot(SpatialCellImpl.java:
441)
[java] at
org.jdesktop.wonderland.server.spatial.impl.SpatialCellImpl.setParent(SpatialCellImpl.java:
454)
[java] at
org.jdesktop.wonderland.server.spatial.impl.SpatialCellImpl.addChild(SpatialCellImpl.java:
176)
[java] at
org.jdesktop.wonderland.server.spatial.UniverseService
$7.run(UniverseService.java:341)
[java] at
org.jdesktop.wonderland.server.spatial.UniverseService
$ChangeApplication.run(UniverseService.java:933)
[java] May 20, 2011 12:37:00 PM
org.jdesktop.wonderland.server.spatial.impl.UniverseImpl
createSpatialCell
[java] FINE: createSpatialCell 49 dsID 997
[java] May 20, 2011 12:37:00 PM
org.jdesktop.wonderland.server.spatial.UniverseService
$ChangeApplication run
[java] WARNING: [UniverseService] Unexpected error in change
thread
[java] java.lang.NullPointerException
[java] at
org.jdesktop.wonderland.server.spatial.impl.SpatialCellImpl.setRoot(SpatialCellImpl.java:
441)
[java] at
org.jdesktop.wonderland.server.spatial.impl.SpatialCellImpl.setParent(SpatialCellImpl.java:
454)
[java] at
org.jdesktop.wonderland.server.spatial.impl.SpatialCellImpl.addChild(SpatialCellImpl.java:
176)
[java] at
org.jdesktop.wonderland.server.spatial.UniverseService
$7.run(UniverseService.java:341)
[java] at
org.jdesktop.wonderland.server.spatial.UniverseService
$ChangeApplication.run(UniverseService.java:933)
[java] May 20, 2011 12:37:00 PM
org.jdesktop.wonderland.server.spatial.impl.UniverseImpl
createSpatialCell
[java] FINE: createSpatialCell 50 dsID 1004
[java] May 20, 2011 12:37:00 PM
org.jdesktop.wonderland.server.spatial.UniverseService
$ChangeApplication run
[java] WARNING: [UniverseService] Unexpected error in change
thread
[java] java.lang.NullPointerException
[java] at
org.jdesktop.wonderland.server.spatial.impl.SpatialCellImpl.setRoot(SpatialCellImpl.java:
441)
[java] at
org.jdesktop.wonderland.server.spatial.impl.SpatialCellImpl.setParent(SpatialCellImpl.java:
454)
[java] at
org.jdesktop.wonderland.server.spatial.impl.SpatialCellImpl.addChild(SpatialCellImpl.java:
176)
[java] at
org.jdesktop.wonderland.server.spatial.UniverseService
$7.run(UniverseService.java:341)
[java] at
org.jdesktop.wonderland.server.spatial.UniverseService
$ChangeApplication.run(UniverseService.java:933)
[java] May 20, 2011 12:37:00 PM
org.jdesktop.wonderland.server.spatial.impl.UniverseImpl
createSpatialCell
[java] FINE: createSpatialCell 51 dsID 1011
[java] May 20, 2011 12:37:00 PM
org.jdesktop.wonderland.server.spatial.UniverseService
$ChangeApplication run
[java] WARNING: [UniverseService] Unexpected error in change
thread
[java] java.lang.NullPointerException
[java] at
org.jdesktop.wonderland.server.spatial.impl.SpatialCellImpl.setRoot(SpatialCellImpl.java:
441)
[java] at
org.jdesktop.wonderland.server.spatial.impl.SpatialCellImpl.setParent(SpatialCellImpl.java:
454)
[java] at
org.jdesktop.wonderland.server.spatial.impl.SpatialCellImpl.addChild(SpatialCellImpl.java:
176)
[java] at
org.jdesktop.wonderland.server.spatial.UniverseService
$7.run(UniverseService.java:341)
[java] at
org.jdesktop.wonderland.server.spatial.UniverseService
$ChangeApplication.run(UniverseService.java:933)

best,
jW

Jonathan Kaplan

unread,
May 20, 2011, 2:37:58 PM5/20/11
to openwon...@googlegroups.com
I think that one is mostly harmless. Are there database errors or out of memory errors near the bottom of the file?

jagwire

unread,
May 20, 2011, 2:45:19 PM5/20/11
to Open Wonderland Forum
Further down the file we find these:

INFO: [WFS Exporter] Writing cell /isocialScreen.dae.gz Copy-4 to
http://128.206.14.35:8080/wonderland-web-wfs/wfs/create/cell
[java] May 20, 2011 12:37:04 PM
com.sun.sgs.impl.service.data.store.db.bdb.BdbEnvironment
$LoggingErrorHandler error
[java] WARNING: Database error message: PANIC: fatal region error
detected; run recovery
[java] java.lang.Exception: Stacktrace
[java] at
com.sun.sgs.impl.service.data.store.db.bdb.BdbEnvironment
$LoggingErrorHandler.error(BdbEnvironment.java:262)
[java] at
com.sleepycat.db.internal.DbEnv.handle_error(DbEnv.java:121)
[java] at
com.sleepycat.db.internal.db_javaJNI.DbEnv_txn_begin(Native Method)
[java] at com.sleepycat.db.internal.DbEnv.txn_begin(DbEnv.java:
451)
[java] at
com.sleepycat.db.TransactionConfig.beginTransaction(TransactionConfig.java:
117)
[java] at
com.sleepycat.db.Environment.beginTransaction(Environment.java:320)
[java] at
com.sun.sgs.impl.service.data.store.db.bdb.BdbTransaction.<init>(BdbTransaction.java:
53)
[java] at
com.sun.sgs.impl.service.data.store.db.bdb.BdbEnvironment.beginTransaction(BdbEnvironment.java:
439)
[java] at com.sun.sgs.impl.service.data.store.DataStoreImpl
$TxnInfo.<init>(DataStoreImpl.java:351)
[java] at
com.sun.sgs.impl.service.data.store.DataStoreImpl.joinTransaction(DataStoreImpl.java:
1466)
[java] at
com.sun.sgs.impl.service.data.store.DataStoreImpl.checkTxn(DataStoreImpl.java:
1432)
[java] at
com.sun.sgs.impl.service.data.store.DataStoreImpl.getBindingInternal(DataStoreImpl.java:
1075)
[java] at
com.sun.sgs.impl.service.data.store.AbstractDataStore.getBinding(AbstractDataStore.java:
393)
[java] at
com.sun.sgs.impl.service.data.store.DataStoreProfileProducer.getBinding(DataStoreProfileProducer.java:
162)
[java] at
com.sun.sgs.impl.service.data.Context.getBinding(Context.java:141)
[java] at
com.sun.sgs.impl.service.data.DataServiceImpl.getBindingInternal(DataServiceImpl.java:
785)
[java] at
com.sun.sgs.impl.service.data.DataServiceImpl.getBinding(DataServiceImpl.java:
530)
[java] at
com.sun.sgs.impl.app.profile.ProfileDataManager.getBinding(ProfileDataManager.java:
49)
[java] at
org.jdesktop.wonderland.server.cell.CellManagerMO.getCell(CellManagerMO.java:
137)
[java] at
org.jdesktop.wonderland.server.wfs.exporter.CellExportService
$GetCellDescriptor.run(CellExportService.java:559)
[java] at
com.sun.sgs.impl.kernel.TransactionSchedulerImpl.executeTask(TransactionSchedulerImpl.java:
619)
[java] at
com.sun.sgs.impl.kernel.TransactionSchedulerImpl.waitForTask(TransactionSchedulerImpl.java:
414)
[java] at
com.sun.sgs.impl.kernel.TransactionSchedulerImpl.runTask(TransactionSchedulerImpl.java:
331)
[java] at
org.jdesktop.wonderland.server.wfs.exporter.CellExportService
$ExportCells.run(CellExportService.java:399)
[java] at java.util.concurrent.Executors
$RunnableAdapter.call(Executors.java:441)
[java] at java.util.concurrent.FutureTask
$Sync.innerRun(FutureTask.java:303)
[java] at java.util.concurrent.FutureTask.run(FutureTask.java:
138)
[java] at java.util.concurrent.ThreadPoolExecutor
$Worker.runTask(ThreadPoolExecutor.java:886)
[java] at java.util.concurrent.ThreadPoolExecutor
$Worker.run(ThreadPoolExecutor.java:908)
[java] at java.lang.Thread.run(Thread.java:662)
[java] May 20, 2011 12:37:04 PM
com.sun.sgs.impl.service.data.store.db.bdb.BdbEnvironment
convertException
[java] SEVERE: Database requires recovery
[java] java.lang.Error: Database requires recovery -- need to
restart: com.sleepycat.db.RunRecoveryException: DB_RUNRECOVERY: Fatal
error, run database recovery: DB_RUNRECOVERY: Fatal error, run
database recovery
[java] at
com.sun.sgs.impl.service.data.store.db.bdb.BdbEnvironment.convertException(BdbEnvironment.java:
416)
[java] at
com.sun.sgs.impl.service.data.store.db.bdb.BdbTransaction.<init>(BdbTransaction.java:
59)
[java] at
com.sun.sgs.impl.service.data.store.db.bdb.BdbEnvironment.beginTransaction(BdbEnvironment.java:
439)
[java] at com.sun.sgs.impl.service.data.store.DataStoreImpl
$TxnInfo.<init>(DataStoreImpl.java:351)
[java] at
com.sun.sgs.impl.service.data.store.DataStoreImpl.joinTransaction(DataStoreImpl.java:
1466)
[java] at
com.sun.sgs.impl.service.data.store.DataStoreImpl.checkTxn(DataStoreImpl.java:
1432)
[java] at
com.sun.sgs.impl.service.data.store.DataStoreImpl.getBindingInternal(DataStoreImpl.java:
1075)
[java] at
com.sun.sgs.impl.service.data.store.AbstractDataStore.getBinding(AbstractDataStore.java:
393)
[java] at
com.sun.sgs.impl.service.data.store.DataStoreProfileProducer.getBinding(DataStoreProfileProducer.java:
162)
[java] at
com.sun.sgs.impl.service.data.Context.getBinding(Context.java:141)
[java] at
com.sun.sgs.impl.service.data.DataServiceImpl.getBindingInternal(DataServiceImpl.java:
785)
[java] at
com.sun.sgs.impl.service.data.DataServiceImpl.getBinding(DataServiceImpl.java:
530)
[java] at
com.sun.sgs.impl.app.profile.ProfileDataManager.getBinding(ProfileDataManager.java:
49)
[java] at
org.jdesktop.wonderland.server.cell.CellManagerMO.getCell(CellManagerMO.java:
137)
[java] at
org.jdesktop.wonderland.server.wfs.exporter.CellExportService
$GetCellDescriptor.run(CellExportService.java:559)
[java] at
com.sun.sgs.impl.kernel.TransactionSchedulerImpl.executeTask(TransactionSchedulerImpl.java:
619)
[java] at
com.sun.sgs.impl.kernel.TransactionSchedulerImpl.waitForTask(TransactionSchedulerImpl.java:
414)
[java] at
com.sun.sgs.impl.kernel.TransactionSchedulerImpl.runTask(TransactionSchedulerImpl.java:
331)
[java] at
org.jdesktop.wonderland.server.wfs.exporter.CellExportService
$ExportCells.run(CellExportService.java:399)
[java] at java.util.concurrent.Executors
$RunnableAdapter.call(Executors.java:441)
[java] at java.util.concurrent.FutureTask
$Sync.innerRun(FutureTask.java:303)
[java] at java.util.concurrent.FutureTask.run(FutureTask.java:
138)
[java] at java.util.concurrent.ThreadPoolExecutor
$Worker.runTask(ThreadPoolExecutor.java:886)
[java] at java.util.concurrent.ThreadPoolExecutor
$Worker.run(ThreadPoolExecutor.java:908)
[java] at java.lang.Thread.run(Thread.java:662)
[java] Caused by: com.sleepycat.db.RunRecoveryException:
DB_RUNRECOVERY: Fatal error, run database recovery: DB_RUNRECOVERY:
Fatal error, run database recovery
[java] at
com.sleepycat.db.internal.db_javaJNI.DbEnv_txn_begin(Native Method)
[java] at com.sleepycat.db.internal.DbEnv.txn_begin(DbEnv.java:
451)
[java] at
com.sleepycat.db.TransactionConfig.beginTransaction(TransactionConfig.java:
117)
[java] at
com.sleepycat.db.Environment.beginTransaction(Environment.java:320)
[java] at
com.sun.sgs.impl.service.data.store.db.bdb.BdbTransaction.<init>(BdbTransaction.java:
53)
[java] ... 23 more
[java] May 20, 2011 12:37:04 PM
com.sun.sgs.impl.service.transaction.TransactionImpl abort
[java] WARNING: abort TransactionImpl[tid:2042, creationTime:
1305913024630, timeout:100, state:ABORTING]
participant:com.sun.sgs.impl.service.data.store.DataStoreImpl
(DataStoreImpl[directory="/home/isocial-admin/.wonderland-server/0.5-
dev/run/darkstar_server/run/core/data/sgs/./dsdb"]) failed
[java] java.lang.IllegalStateException: Transaction not active
[java] at com.sun.sgs.impl.service.data.store.DataStoreImpl
$ThreadTxnInfoTable.remove(DataStoreImpl.java:299)
[java] at
com.sun.sgs.impl.service.data.store.DataStoreImpl.abortInternal(DataStoreImpl.java:
1332)
[java] at
com.sun.sgs.impl.service.data.store.AbstractDataStore.abort(AbstractDataStore.java:
891)
[java] at
com.sun.sgs.impl.service.transaction.TransactionImpl.abort(TransactionImpl.java:
258)
[java] at
com.sun.sgs.impl.kernel.TransactionSchedulerImpl.executeTask(TransactionSchedulerImpl.java:
665)
[java] at
com.sun.sgs.impl.kernel.TransactionSchedulerImpl.waitForTask(TransactionSchedulerImpl.java:
414)
[java] at
com.sun.sgs.impl.kernel.TransactionSchedulerImpl.runTask(TransactionSchedulerImpl.java:
331)
[java] at
org.jdesktop.wonderland.server.wfs.exporter.CellExportService
$ExportCells.run(CellExportService.java:399)
[java] at java.util.concurrent.Executors
$RunnableAdapter.call(Executors.java:441)
[java] at java.util.concurrent.FutureTask
$Sync.innerRun(FutureTask.java:303)
[java] at java.util.concurrent.FutureTask.run(FutureTask.java:
138)
[java] at java.util.concurrent.ThreadPoolExecutor
$Worker.runTask(ThreadPoolExecutor.java:886)
[java] at java.util.concurrent.ThreadPoolExecutor
$Worker.run(ThreadPoolExecutor.java:908)
[java] at java.lang.Thread.run(Thread.java:662)
[java] May 20, 2011 12:37:04 PM
com.sun.sgs.impl.kernel.TransactionSchedulerImpl shouldRetry
[java] WARNING: dropping a task that failed with a non-retryable
exception:
org.jdesktop.wonderland.server.wfs.exporter.CellExportService.GET_CELL_DESCRIPTOR[owner:app:Wonderland]
[java] java.lang.Error: Database requires recovery -- need to
restart: com.sleepycat.db.RunRecoveryException: DB_RUNRECOVERY: Fatal
error, run database recovery: DB_RUNRECOVERY: Fatal error, run
database recovery
[java] at
com.sun.sgs.impl.service.data.store.db.bdb.BdbEnvironment.convertException(BdbEnvironment.java:
416)
[java] at
com.sun.sgs.impl.service.data.store.db.bdb.BdbTransaction.<init>(BdbTransaction.java:
59)
[java] at
com.sun.sgs.impl.service.data.store.db.bdb.BdbEnvironment.beginTransaction(BdbEnvironment.java:
439)
[java] at com.sun.sgs.impl.service.data.store.DataStoreImpl
$TxnInfo.<init>(DataStoreImpl.java:351)
[java] at
com.sun.sgs.impl.service.data.store.DataStoreImpl.joinTransaction(DataStoreImpl.java:
1466)
[java] at
com.sun.sgs.impl.service.data.store.DataStoreImpl.checkTxn(DataStoreImpl.java:
1432)
[java] at
com.sun.sgs.impl.service.data.store.DataStoreImpl.getBindingInternal(DataStoreImpl.java:
1075)
[java] at
com.sun.sgs.impl.service.data.store.AbstractDataStore.getBinding(AbstractDataStore.java:
393)
[java] at
com.sun.sgs.impl.service.data.store.DataStoreProfileProducer.getBinding(DataStoreProfileProducer.java:
162)
[java] at
com.sun.sgs.impl.service.data.Context.getBinding(Context.java:141)
[java] at
com.sun.sgs.impl.service.data.DataServiceImpl.getBindingInternal(DataServiceImpl.java:
785)
[java] at
com.sun.sgs.impl.service.data.DataServiceImpl.getBinding(DataServiceImpl.java:
530)
[java] at
com.sun.sgs.impl.app.profile.ProfileDataManager.getBinding(ProfileDataManager.java:
49)
[java] at
org.jdesktop.wonderland.server.cell.CellManagerMO.getCell(CellManagerMO.java:
137)
[java] at
org.jdesktop.wonderland.server.wfs.exporter.CellExportService
$GetCellDescriptor.run(CellExportService.java:559)
[java] at
com.sun.sgs.impl.kernel.TransactionSchedulerImpl.executeTask(TransactionSchedulerImpl.java:
619)
[java] at
com.sun.sgs.impl.kernel.TransactionSchedulerImpl.waitForTask(TransactionSchedulerImpl.java:
414)
[java] at
com.sun.sgs.impl.kernel.TransactionSchedulerImpl.runTask(TransactionSchedulerImpl.java:
331)
[java] at
org.jdesktop.wonderland.server.wfs.exporter.CellExportService
$ExportCells.run(CellExportService.java:399)
[java] at java.util.concurrent.Executors
$RunnableAdapter.call(Executors.java:441)
[java] at java.util.concurrent.FutureTask
$Sync.innerRun(FutureTask.java:303)
[java] at java.util.concurrent.FutureTask.run(FutureTask.java:
138)
[java] at java.util.concurrent.ThreadPoolExecutor
$Worker.runTask(ThreadPoolExecutor.java:886)
[java] at java.util.concurrent.ThreadPoolExecutor
$Worker.run(ThreadPoolExecutor.java:908)
[java] at java.lang.Thread.run(Thread.java:662)
[java] Caused by: com.sleepycat.db.RunRecoveryException:
DB_RUNRECOVERY: Fatal error, run database recovery: DB_RUNRECOVERY:
Fatal error, run database recovery
[java] at
com.sleepycat.db.internal.db_javaJNI.DbEnv_txn_begin(Native Method)
[java] at com.sleepycat.db.internal.DbEnv.txn_begin(DbEnv.java:
451)
[java] at
com.sleepycat.db.TransactionConfig.beginTransaction(TransactionConfig.java:
117)
[java] at
com.sleepycat.db.Environment.beginTransaction(Environment.java:320)
[java] at
com.sun.sgs.impl.service.data.store.db.bdb.BdbTransaction.<init>(BdbTransaction.java:
53)
[java] ... 23 more

along with several similar fatal error sort of stack traces...

jW
Reply all
Reply to author
Forward
0 new messages