Attachment 223318 Details for Bug 254330 – Full exception, mongodb log and server log

Full exception, mongodb log and server log

logs.txt (text/plain), 16.51 KB, created by fulder on 2021-03-16 09:35:56 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: fulder

Created: 2021-03-16 09:35:56 UTC

Size: 16.51 KB

patch

obsolete

>Starting controller manually:
>
>>  /usr/local/openjdk8/bin/java -Djava.awt.headless=true -Xmx1024M -jar /usr/local/share/java/unifi/lib/ace.jar start
>org.tuckey.web.filters.urlrewrite.UrlRewriteFilter INFO: destroy called
>Exception in thread "launcher" org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'Ã00000' defined in class com.ubnt.service.AppContext: Instantiation of bean failed; nested exception is org.springframework.beans.factory.BeanDefinitionStoreException: Factory method [com.ubnt.service.P.D com.ubnt.service.AppContext.Ã00000()] threw exception; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'dbService' defined in class com.ubnt.service.AppContext: Invocation of init method failed; nested exception is com.mongodb.CommandFailureException: { "serverUsed" : "127.0.0.1:27117" , "ok" : 0.0 , "errmsg" : "interrupted at shutdown" , "code" : 11600 , "codeName" : "InterruptedAtShutdown"}
>	at org.springframework.beans.factory.support.ConstructorResolver.instantiateUsingFactoryMethod(ConstructorResolver.java:597)
>	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.instantiateUsingFactoryMethod(AbstractAutowireCapableBeanFactory.java:1055)
>	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:951)
>	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:487)
>	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:458)
>	at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:296)
>	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:223)
>	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:293)
>	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:194)
>	at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:628)
>	at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:932)
>	at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:479)
>	at org.springframework.context.annotation.AnnotationConfigApplicationContext.<init>(AnnotationConfigApplicationContext.java:73)
>	at com.ubnt.service.B.ÃO0000(Unknown Source)
>	at com.ubnt.service.B.String(Unknown Source)
>	at com.ubnt.ace.Launcher.main(Unknown Source)
>Caused by: org.springframework.beans.factory.BeanDefinitionStoreException: Factory method [com.ubnt.service.P.D com.ubnt.service.AppContext.Ã00000()] threw exception; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'dbService' defined in class com.ubnt.service.AppContext: Invocation of init method failed; nested exception is com.mongodb.CommandFailureException: { "serverUsed" : "127.0.0.1:27117" , "ok" : 0.0 , "errmsg" : "interrupted at shutdown" , "code" : 11600 , "codeName" : "InterruptedAtShutdown"}
>	at org.springframework.beans.factory.support.SimpleInstantiationStrategy.instantiate(SimpleInstantiationStrategy.java:181)
>	at org.springframework.beans.factory.support.ConstructorResolver.instantiateUsingFactoryMethod(ConstructorResolver.java:586)
>	... 15 more
>Caused by: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'dbService' defined in class com.ubnt.service.AppContext: Invocation of init method failed; nested exception is com.mongodb.CommandFailureException: { "serverUsed" : "127.0.0.1:27117" , "ok" : 0.0 , "errmsg" : "interrupted at shutdown" , "code" : 11600 , "codeName" : "InterruptedAtShutdown"}
>	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1512)
>	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:521)
>	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:458)
>	at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:296)
>	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:223)
>	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:293)
>	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:194)
>	at org.springframework.context.annotation.ConfigurationClassEnhancer$BeanMethodInterceptor.intercept(ConfigurationClassEnhancer.java:305)
>	at com.ubnt.service.AppContext$$EnhancerBySpringCGLIB$$478a80d4.dbService(<generated>)
>	at com.ubnt.service.AppContext.Ã00000(Unknown Source)
>	at com.ubnt.service.AppContext$$EnhancerBySpringCGLIB$$478a80d4.CGLIB$Ã00000$1(<generated>)
>	at com.ubnt.service.AppContext$$EnhancerBySpringCGLIB$$478a80d4$$FastClassBySpringCGLIB$$850eaa78.invoke(<generated>)
>	at org.springframework.cglib.proxy.MethodProxy.invokeSuper(MethodProxy.java:228)
>	at org.springframework.context.annotation.ConfigurationClassEnhancer$BeanMethodInterceptor.intercept(ConfigurationClassEnhancer.java:293)
>	at com.ubnt.service.AppContext$$EnhancerBySpringCGLIB$$478a80d4.Ã00000(<generated>)
>	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
>	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>	at java.lang.reflect.Method.invoke(Method.java:498)
>	at org.springframework.beans.factory.support.SimpleInstantiationStrategy.instantiate(SimpleInstantiationStrategy.java:160)
>	... 16 more
>Caused by: com.mongodb.CommandFailureException: { "serverUsed" : "127.0.0.1:27117" , "ok" : 0.0 , "errmsg" : "interrupted at shutdown" , "code" : 11600 , "codeName" : "InterruptedAtShutdown"}
>	at com.mongodb.CommandResult.getException(CommandResult.java:76)
>	at com.mongodb.CommandResult.throwOnError(CommandResult.java:140)
>	at com.mongodb.DBApiLayer.getCollectionNames(DBApiLayer.java:154)
>	at com.ubnt.service.new.o00O.Ã´o0000(Unknown Source)
>	at com.ubnt.service.new.o00O.afterPropertiesSet(Unknown Source)
>	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1571)
>	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1509)
>	... 35 more
>
>
>
>Mongodb log:
>
>2021-03-16T10:22:45.636+0100 I CONTROL  [main] ***** SERVER RESTARTED *****
>2021-03-16T10:22:45.641+0100 I CONTROL  [initandlisten] MongoDB starting : pid=4457 port=27117 dbpath=/usr/local/share/java/unifi/data/db 64-bit host=unifi-test
>2021-03-16T10:22:45.641+0100 I CONTROL  [initandlisten] db version v3.6.22
>2021-03-16T10:22:45.641+0100 I CONTROL  [initandlisten] git version: 62d9f36d148e4dacfec1ca8fcb110f1cc410336f
>2021-03-16T10:22:45.641+0100 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.1.1h-freebsd  22 Sep 2020
>2021-03-16T10:22:45.641+0100 I CONTROL  [initandlisten] allocator: system
>2021-03-16T10:22:45.641+0100 I CONTROL  [initandlisten] modules: none
>2021-03-16T10:22:45.641+0100 I CONTROL  [initandlisten] build environment:
>2021-03-16T10:22:45.641+0100 I CONTROL  [initandlisten]     distarch: x86_64
>2021-03-16T10:22:45.641+0100 I CONTROL  [initandlisten]     target_arch: x86_64
>2021-03-16T10:22:45.642+0100 I CONTROL  [initandlisten] options: { net: { bindIp: "127.0.0.1", port: 27117, unixDomainSocket: { pathPrefix: "/usr/local/share/java/unifi/run" } }, storage: { dbPath: "/usr/local/share/java/unifi/data/db" }, systemLog: { destination: "file", logAppend: true, path: "/usr/local/share/java/unifi/logs/mongod.log" } }
>2021-03-16T10:22:45.642+0100 I -        [initandlisten] Detected data files in /usr/local/share/java/unifi/data/db created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
>2021-03-16T10:22:45.642+0100 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=15813M,cache_overflow=(file_max=0M),session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),compatibility=(release="3.0",require_max="3.0"),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),statistics_log=(wait=0),verbose=(recovery_progress),
>2021-03-16T10:22:47.415+0100 I STORAGE  [initandlisten] WiredTiger message [1615886567:415270][4457:0x80491a000], txn-recover: Main recovery loop: starting at 5/7296
>2021-03-16T10:22:47.490+0100 I STORAGE  [initandlisten] WiredTiger message [1615886567:490344][4457:0x80491a000], txn-recover: Recovering log 5 through 6
>2021-03-16T10:22:47.651+0100 I STORAGE  [initandlisten] WiredTiger message [1615886567:651915][4457:0x80491a000], txn-recover: Recovering log 6 through 6
>2021-03-16T10:22:47.692+0100 I STORAGE  [initandlisten] WiredTiger message [1615886567:692851][4457:0x80491a000], txn-recover: Set global recovery timestamp: 0
>2021-03-16T10:22:48.311+0100 I CONTROL  [initandlisten] 
>2021-03-16T10:22:48.311+0100 I CONTROL  [initandlisten] ** WARNING: Access control is not enabled for the database.
>2021-03-16T10:22:48.311+0100 I CONTROL  [initandlisten] **          Read and write access to data and configuration is unrestricted.
>2021-03-16T10:22:48.311+0100 I CONTROL  [initandlisten] ** WARNING: You are running this process as the root user, which is not recommended.
>2021-03-16T10:22:48.311+0100 I CONTROL  [initandlisten] 
>2021-03-16T10:22:48.311+0100 I CONTROL  [initandlisten] 
>2021-03-16T10:22:48.311+0100 I CONTROL  [initandlisten] ** WARNING: soft rlimits too low. rlimits set to 34232 processes, 940356 files. Number of processes should be at least 470178 : 0.5 times number of files.
>2021-03-16T10:22:48.313+0100 I FTDC     [initandlisten] Initializing full-time diagnostic data capture with directory '/usr/local/share/java/unifi/data/db/diagnostic.data'
>2021-03-16T10:22:48.314+0100 I NETWORK  [initandlisten] listening via socket bound to 127.0.0.1
>2021-03-16T10:22:48.314+0100 I NETWORK  [initandlisten] listening via socket bound to /usr/local/share/java/unifi/run/mongodb-27117.sock
>2021-03-16T10:22:48.314+0100 I NETWORK  [initandlisten] waiting for connections on port 27117
>2021-03-16T10:22:48.576+0100 I NETWORK  [listener] connection accepted from 127.0.0.1:43840 #1 (1 connection now open)
>2021-03-16T10:22:48.590+0100 I NETWORK  [listener] connection accepted from 127.0.0.1:59457 #2 (2 connections now open)
>2021-03-16T10:22:48.632+0100 I NETWORK  [listener] connection accepted from 127.0.0.1:60932 #3 (3 connections now open)
>2021-03-16T10:22:48.635+0100 I NETWORK  [listener] connection accepted from 127.0.0.1:12882 #4 (4 connections now open)
>2021-03-16T10:22:48.635+0100 I COMMAND  [conn4] terminating, shutdown command received
>2021-03-16T10:22:48.635+0100 I NETWORK  [conn4] shutdown: going to close listening sockets...
>2021-03-16T10:22:48.635+0100 I NETWORK  [conn4] removing socket file: /usr/local/share/java/unifi/run/mongodb-27117.sock
>2021-03-16T10:22:48.636+0100 I FTDC     [conn4] Shutting down full-time diagnostic data capture
>2021-03-16T10:22:48.636+0100 I STORAGE  [conn4] WiredTigerKVEngine shutting down
>2021-03-16T10:22:49.353+0100 I STORAGE  [conn4] shutdown: removing fs lock...
>2021-03-16T10:22:49.353+0100 I CONTROL  [conn4] now exiting
>2021-03-16T10:22:49.353+0100 I CONTROL  [conn4] shutting down with code:0
>
>
>
>
>Server log:
>
>2021-03-16T10:22:45.636+0100 I CONTROL  [main] ***** SERVER RESTARTED *****
>2021-03-16T10:22:45.641+0100 I CONTROL  [initandlisten] MongoDB starting : pid=4457 port=27117 dbpath=/usr/local/share/java/unifi/data/db 64-bit host=unifi-test
>2021-03-16T10:22:45.641+0100 I CONTROL  [initandlisten] db version v3.6.22
>2021-03-16T10:22:45.641+0100 I CONTROL  [initandlisten] git version: 62d9f36d148e4dacfec1ca8fcb110f1cc410336f
>2021-03-16T10:22:45.641+0100 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.1.1h-freebsd  22 Sep 2020
>2021-03-16T10:22:45.641+0100 I CONTROL  [initandlisten] allocator: system
>2021-03-16T10:22:45.641+0100 I CONTROL  [initandlisten] modules: none
>2021-03-16T10:22:45.641+0100 I CONTROL  [initandlisten] build environment:
>2021-03-16T10:22:45.641+0100 I CONTROL  [initandlisten]     distarch: x86_64
>2021-03-16T10:22:45.641+0100 I CONTROL  [initandlisten]     target_arch: x86_64
>2021-03-16T10:22:45.642+0100 I CONTROL  [initandlisten] options: { net: { bindIp: "127.0.0.1", port: 27117, unixDomainSocket: { pathPrefix: "/usr/local/share/java/unifi/run" } }, storage: { dbPath: "/usr/local/share/java/unifi/data/db" }, systemLog: { destination: "file", logAppend: true, path: "/usr/local/share/java/unifi/logs/mongod.log" } }
>2021-03-16T10:22:45.642+0100 I -        [initandlisten] Detected data files in /usr/local/share/java/unifi/data/db created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
>2021-03-16T10:22:45.642+0100 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=15813M,cache_overflow=(file_max=0M),session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),compatibility=(release="3.0",require_max="3.0"),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),statistics_log=(wait=0),verbose=(recovery_progress),
>2021-03-16T10:22:47.415+0100 I STORAGE  [initandlisten] WiredTiger message [1615886567:415270][4457:0x80491a000], txn-recover: Main recovery loop: starting at 5/7296
>2021-03-16T10:22:47.490+0100 I STORAGE  [initandlisten] WiredTiger message [1615886567:490344][4457:0x80491a000], txn-recover: Recovering log 5 through 6
>2021-03-16T10:22:47.651+0100 I STORAGE  [initandlisten] WiredTiger message [1615886567:651915][4457:0x80491a000], txn-recover: Recovering log 6 through 6
>2021-03-16T10:22:47.692+0100 I STORAGE  [initandlisten] WiredTiger message [1615886567:692851][4457:0x80491a000], txn-recover: Set global recovery timestamp: 0
>2021-03-16T10:22:48.311+0100 I CONTROL  [initandlisten] 
>2021-03-16T10:22:48.311+0100 I CONTROL  [initandlisten] ** WARNING: Access control is not enabled for the database.
>2021-03-16T10:22:48.311+0100 I CONTROL  [initandlisten] **          Read and write access to data and configuration is unrestricted.
>2021-03-16T10:22:48.311+0100 I CONTROL  [initandlisten] ** WARNING: You are running this process as the root user, which is not recommended.
>2021-03-16T10:22:48.311+0100 I CONTROL  [initandlisten] 
>2021-03-16T10:22:48.311+0100 I CONTROL  [initandlisten] 
>2021-03-16T10:22:48.311+0100 I CONTROL  [initandlisten] ** WARNING: soft rlimits too low. rlimits set to 34232 processes, 940356 files. Number of processes should be at least 470178 : 0.5 times number of files.
>2021-03-16T10:22:48.313+0100 I FTDC     [initandlisten] Initializing full-time diagnostic data capture with directory '/usr/local/share/java/unifi/data/db/diagnostic.data'
>2021-03-16T10:22:48.314+0100 I NETWORK  [initandlisten] listening via socket bound to 127.0.0.1
>2021-03-16T10:22:48.314+0100 I NETWORK  [initandlisten] listening via socket bound to /usr/local/share/java/unifi/run/mongodb-27117.sock
>2021-03-16T10:22:48.314+0100 I NETWORK  [initandlisten] waiting for connections on port 27117
>2021-03-16T10:22:48.576+0100 I NETWORK  [listener] connection accepted from 127.0.0.1:43840 #1 (1 connection now open)
>2021-03-16T10:22:48.590+0100 I NETWORK  [listener] connection accepted from 127.0.0.1:59457 #2 (2 connections now open)
>2021-03-16T10:22:48.632+0100 I NETWORK  [listener] connection accepted from 127.0.0.1:60932 #3 (3 connections now open)
>2021-03-16T10:22:48.635+0100 I NETWORK  [listener] connection accepted from 127.0.0.1:12882 #4 (4 connections now open)
>2021-03-16T10:22:48.635+0100 I COMMAND  [conn4] terminating, shutdown command received
>2021-03-16T10:22:48.635+0100 I NETWORK  [conn4] shutdown: going to close listening sockets...
>2021-03-16T10:22:48.635+0100 I NETWORK  [conn4] removing socket file: /usr/local/share/java/unifi/run/mongodb-27117.sock
>2021-03-16T10:22:48.636+0100 I FTDC     [conn4] Shutting down full-time diagnostic data capture
>2021-03-16T10:22:48.636+0100 I STORAGE  [conn4] WiredTigerKVEngine shutting down
>2021-03-16T10:22:49.353+0100 I STORAGE  [conn4] shutdown: removing fs lock...
>2021-03-16T10:22:49.353+0100 I CONTROL  [conn4] now exiting
>2021-03-16T10:22:49.353+0100 I CONTROL  [conn4] shutting down with code:0
>
>

Actions: View

Attachments on bug 254330: 223318