添加邮箱验证不成功，请问是什么原因

九月 02, 2017 11:54:11 上午 org.apache.tomcat.util.digester.SetPropertiesRule begin
警告: [SetPropertiesRule]{Server/Service/Engine/Host/Context} Setting property 'source' to 'org.eclipse.jst.jee.server:nutzbook' did not find a matching property.
九月 02, 2017 11:54:11 上午 org.apache.catalina.startup.VersionLoggerListener log
信息: Server version:        Apache Tomcat/9.0.0.M17
九月 02, 2017 11:54:11 上午 org.apache.catalina.startup.VersionLoggerListener log
信息: Server built:          Jan 10 2017 20:59:20 UTC
九月 02, 2017 11:54:11 上午 org.apache.catalina.startup.VersionLoggerListener log
信息: Server number:         9.0.0.0
九月 02, 2017 11:54:11 上午 org.apache.catalina.startup.VersionLoggerListener log
信息: OS Name:               Windows 7
九月 02, 2017 11:54:11 上午 org.apache.catalina.startup.VersionLoggerListener log
信息: OS Version:            6.1
九月 02, 2017 11:54:11 上午 org.apache.catalina.startup.VersionLoggerListener log
信息: Architecture:          amd64
九月 02, 2017 11:54:11 上午 org.apache.catalina.startup.VersionLoggerListener log
信息: Java Home:             C:\jre1.8
九月 02, 2017 11:54:11 上午 org.apache.catalina.startup.VersionLoggerListener log
信息: JVM Version:           1.8.0_144-b01
九月 02, 2017 11:54:11 上午 org.apache.catalina.startup.VersionLoggerListener log
信息: JVM Vendor:            Oracle Corporation
九月 02, 2017 11:54:11 上午 org.apache.catalina.startup.VersionLoggerListener log
信息: CATALINA_BASE:         E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0
九月 02, 2017 11:54:11 上午 org.apache.catalina.startup.VersionLoggerListener log
信息: CATALINA_HOME:         E:\nutzproject\apache-tomcat-9.0.0.M17
九月 02, 2017 11:54:11 上午 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Dcatalina.base=E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0
九月 02, 2017 11:54:11 上午 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Dcatalina.home=E:\nutzproject\apache-tomcat-9.0.0.M17
九月 02, 2017 11:54:11 上午 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Dwtp.deploy=E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps
九月 02, 2017 11:54:11 上午 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Djava.endorsed.dirs=E:\nutzproject\apache-tomcat-9.0.0.M17\endorsed
九月 02, 2017 11:54:11 上午 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Dfile.encoding=UTF-8
九月 02, 2017 11:54:11 上午 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Xmx512M
九月 02, 2017 11:54:11 上午 org.apache.catalina.core.AprLifecycleListener lifecycleEvent
信息: The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: C:\jre1.8\bin;C:\Windows\Sun\Java\bin;C:\Windows\system32;C:\Windows;C:/jre1.8/bin/server;C:/jre1.8/bin;C:/jre1.8/lib/amd64;C:\ProgramData\Oracle\Java\javapath;E:\server\apache-maven-3.5.0\bin;C:\jdk1.7\bin;C:\jdk1.7\jre\bin;C:\Program Files (x86)\NVIDIA Corporation\PhysX\Common;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0\;;C:\Program Files (x86)\GtkSharp\2.12\bin;D:\php-mysql\bin;C:\Program Files\MySQL\MySQL Server 5.5\bin;D:\server\php-5.3.6-Win32-VC9-x64\ext;E:\nutzproject\eclipse;;.
九月 02, 2017 11:54:12 上午 org.apache.coyote.AbstractProtocol init
信息: Initializing ProtocolHandler ["http-nio-8080"]
九月 02, 2017 11:54:12 上午 org.apache.tomcat.util.net.NioSelectorPool getSharedSelector
信息: Using a shared selector for servlet write/read
九月 02, 2017 11:54:12 上午 org.apache.coyote.AbstractProtocol init
信息: Initializing ProtocolHandler ["ajp-nio-8009"]
九月 02, 2017 11:54:12 上午 org.apache.tomcat.util.net.NioSelectorPool getSharedSelector
信息: Using a shared selector for servlet write/read
九月 02, 2017 11:54:12 上午 org.apache.catalina.startup.Catalina load
信息: Initialization processed in 1781 ms
九月 02, 2017 11:54:12 上午 org.apache.catalina.core.StandardService startInternal
信息: Starting service Catalina
九月 02, 2017 11:54:12 上午 org.apache.catalina.core.StandardEngine startInternal
信息: Starting Servlet Engine: Apache Tomcat/9.0.0.M17
九月 02, 2017 11:54:15 上午 org.apache.jasper.servlet.TldScanner scanJars
信息: At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
九月 02, 2017 11:54:15 上午 org.apache.catalina.core.ApplicationContext log
信息: Initializing Shiro environment
2017-09-02 11:54:15,527 org.apache.shiro.web.env.EnvironmentLoader.initEnvironment(EnvironmentLoader.java:128) INFO  - Starting Shiro environment initialization.
2017-09-02 11:54:15,557 org.apache.shiro.web.env.IniWebEnvironment.init(IniWebEnvironment.java:76) DEBUG - Checking any specified config locations.
2017-09-02 11:54:15,559 org.apache.shiro.web.env.IniWebEnvironment.init(IniWebEnvironment.java:81) DEBUG - No INI instance or config locations specified.  Trying default config locations.
2017-09-02 11:54:15,569 org.apache.shiro.io.ResourceUtils.loadFromClassPath(ResourceUtils.java:159) DEBUG - Opening resource from class path [shiro.ini]
2017-09-02 11:54:15,580 org.apache.shiro.config.Ini.load(Ini.java:351) DEBUG - Parsing [main]
2017-09-02 11:54:15,581 org.apache.shiro.config.Ini.load(Ini.java:351) DEBUG - Parsing [urls]
2017-09-02 11:54:15,584 org.apache.shiro.web.env.IniWebEnvironment.getDefaultIni(IniWebEnvironment.java:136) DEBUG - Discovered non-empty INI configuration at location 'classpath:shiro.ini'.  Using for configuration.
2017-09-02 11:54:15,593 org.apache.shiro.config.IniFactorySupport.createInstance(IniFactorySupport.java:122) DEBUG - Creating instance from Ini [sections=urls]
2017-09-02 11:54:16,250 org.apache.shiro.config.IniFactorySupport.createInstance(IniFactorySupport.java:122) DEBUG - Creating instance from Ini [sections=urls]
2017-09-02 11:54:16,257 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.createChain(DefaultFilterChainManager.java:127) DEBUG - Creating chain [/*] from String definition [anon]
2017-09-02 11:54:16,258 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.applyChainConfig(DefaultFilterChainManager.java:278) DEBUG - Attempting to apply path [/*] to filter [anon] with config [null]
2017-09-02 11:54:16,260 org.apache.shiro.web.env.EnvironmentLoader.initEnvironment(EnvironmentLoader.java:136) DEBUG - Published WebEnvironment as ServletContext attribute with name [org.apache.shiro.web.env.EnvironmentLoader.ENVIRONMENT_ATTRIBUTE_KEY]
2017-09-02 11:54:16,260 org.apache.shiro.web.env.EnvironmentLoader.initEnvironment(EnvironmentLoader.java:141) INFO  - Shiro environment initialized in 728 ms.
2017-09-02 11:54:16,317 org.nutz.mvc.NutFilter._init(NutFilter.java:81) INFO  - NutFilter[nutz] starting ...
2017-09-02 11:54:16,457 org.nutz.resource.Scans.<init>(Scans.java:509) DEBUG - Locations for Scans:
[Dir[path=E:\nutzproject\eclipse], Jar[path=E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\nutz-1.r.60.jar], Dir[path=E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\classes], Jar[path=E:\nutzproject\apache-tomcat-9.0.0.M17\bin\bootstrap.jar], Jar[path=E:\nutzproject\apache-tomcat-9.0.0.M17\bin\tomcat-juli.jar]]
2017-09-02 11:54:16,758 org.nutz.resource.Scans.init(Scans.java:105) DEBUG - Locations for Scans:
{E:\nutzproject\eclipse=Dir[path=E:\nutzproject\eclipse], E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\nutz-1.r.60.jar=Jar[path=E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\nutz-1.r.60.jar], E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\classes=Dir[path=E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\classes], E:\nutzproject\apache-tomcat-9.0.0.M17\bin\bootstrap.jar=Jar[path=E:\nutzproject\apache-tomcat-9.0.0.M17\bin\bootstrap.jar], E:\nutzproject\apache-tomcat-9.0.0.M17\bin\tomcat-juli.jar=Jar[path=E:\nutzproject\apache-tomcat-9.0.0.M17\bin\tomcat-juli.jar], E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\taglibs-standard-impl-1.2.5.jar=Jar[path=E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\taglibs-standard-impl-1.2.5.jar], E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\commons-beanutils-1.9.3.jar=Jar[path=E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\commons-beanutils-1.9.3.jar], E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\slf4j-log4j12-1.7.25.jar=Jar[path=E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\slf4j-log4j12-1.7.25.jar], E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\javax.mail-1.5.2.jar=Jar[path=E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\javax.mail-1.5.2.jar], E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\commons-logging-1.2.jar=Jar[path=E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\commons-logging-1.2.jar], E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\taglibs-standard-spec-1.2.5.jar=Jar[path=E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\taglibs-standard-spec-1.2.5.jar], E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\quartz-2.2.3.jar=Jar[path=E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\quartz-2.2.3.jar], E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\log4j-1.2.17.jar=Jar[path=E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\log4j-1.2.17.jar], E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\taglibs-standard-jstlel-1.2.5.jar=Jar[path=E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\taglibs-standard-jstlel-1.2.5.jar], E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\nutz-integration-quartz-1.r.60.r2.jar=Jar[path=E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\nutz-integration-quartz-1.r.60.r2.jar], E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\slf4j-api-1.7.25.jar=Jar[path=E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\slf4j-api-1.7.25.jar], E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\nutz-integration-shiro-1.r.60.r2.jar=Jar[path=E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\nutz-integration-shiro-1.r.60.r2.jar], E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\druid-1.0.26.jar=Jar[path=E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\druid-1.0.26.jar], E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\mysql-connector-java-5.1.40.jar=Jar[path=E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\mysql-connector-java-5.1.40.jar], E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\commons-email-1.3.3.jar=Jar[path=E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\commons-email-1.3.3.jar], E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\shiro-all-1.3.2.jar=Jar[path=E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\lib\shiro-all-1.3.2.jar]}
2017-09-02 11:54:16,900 org.nutz.castor.Castors.reload(Castors.java:115) DEBUG - Using 95 castor for Castors
2017-09-02 11:54:16,964 org.nutz.mvc.config.AbstractNutConfig.createLoading(AbstractNutConfig.java:59) DEBUG - Loading by class org.nutz.mvc.impl.NutLoading
2017-09-02 11:54:16,971 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:55) INFO  - Nutz Version : 1.r.60 
2017-09-02 11:54:16,972 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:56) INFO  - Nutz.Mvc[nutz] is initializing ...
2017-09-02 11:54:16,972 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:60) DEBUG - Web Container Information:
2017-09-02 11:54:16,974 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:61) DEBUG -  - Default Charset : UTF-8
2017-09-02 11:54:16,975 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:62) DEBUG -  - Current . path  : E:\nutzproject\eclipse\.
2017-09-02 11:54:16,975 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:63) DEBUG -  - Java Version    : 1.8.0_144
2017-09-02 11:54:16,975 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:64) DEBUG -  - File separator  : \
2017-09-02 11:54:16,976 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:65) DEBUG -  - Timezone        : Asia/Shanghai
2017-09-02 11:54:16,976 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:66) DEBUG -  - OS              : Windows 7 amd64
2017-09-02 11:54:16,977 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:67) DEBUG -  - ServerInfo      : Apache Tomcat/9.0.0.M17
2017-09-02 11:54:16,978 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:68) DEBUG -  - Servlet API     : 4.0
2017-09-02 11:54:16,978 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:73) DEBUG -  - ContextPath     : /nutzbook
2017-09-02 11:54:16,978 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:74) DEBUG -  - context.tempdir : E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\work\Catalina\localhost\nutzbook
2017-09-02 11:54:16,979 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:75) DEBUG -  - MainModule      : net.wendal.nutzbook.MainModule
2017-09-02 11:54:16,985 org.nutz.mvc.impl.NutLoading.createContext(NutLoading.java:238) DEBUG - >> app.root = E:/eclipsework/.metadata/.plugins/org.eclipse.wst.server.core/tmp0/wtpwebapps/nutzbook
2017-09-02 11:54:16,990 org.nutz.mvc.impl.NutLoading.createIoc(NutLoading.java:379) DEBUG - @IocBy(type=org.nutz.mvc.ioc.provider.ComboIocProvider, args=["*js", "ioc/", "*anno", "net.wendal.nutzbook", "*tx", "*quartz"],init=[])
2017-09-02 11:54:17,032 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 2 resource by src( ioc/ ) , regex( ^(.+[.])(js|json)$ )
2017-09-02 11:54:17,033 org.nutz.ioc.loader.json.JsonLoader.<init>(JsonLoader.java:48) DEBUG - loading ioc js config from [dao.js]
2017-09-02 11:54:17,044 org.nutz.ioc.loader.json.JsonLoader.<init>(JsonLoader.java:48) DEBUG - loading ioc js config from [mail.js]
2017-09-02 11:54:17,045 org.nutz.ioc.loader.json.JsonLoader.<init>(JsonLoader.java:56) DEBUG - Loaded 5 bean define from path=[ioc/] --> [conf, dao, emailAuthenticator, dataSource, htmlEmail]
2017-09-02 11:54:17,064 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 12 resource by src( net/wendal/nutzbook/ ) , regex( ^.+[.]class$ )
2017-09-02 11:54:17,126 org.nutz.ioc.loader.annotation.AnnotationIocLoader.addClass(AnnotationIocLoader.java:230) WARN  - class(net.wendal.nutzbook.module.BaseModule) don't has @IocBean, but field(dao) has @Inject! Miss @IocBean ??
2017-09-02 11:54:17,142 org.nutz.ioc.loader.annotation.AnnotationIocLoader.addClass(AnnotationIocLoader.java:74) DEBUG - Found @IocBean : class net.wendal.nutzbook.module.UserModule
2017-09-02 11:54:17,166 org.nutz.ioc.loader.annotation.AnnotationIocLoader.addClass(AnnotationIocLoader.java:74) DEBUG - Found @IocBean : class net.wendal.nutzbook.module.UserProfileModule
2017-09-02 11:54:17,201 org.nutz.ioc.loader.annotation.AnnotationIocLoader.addClass(AnnotationIocLoader.java:230) WARN  - class(net.wendal.nutzbook.service.EmailServiceImpl) don't has @IocBean, but field(ioc) has @Inject! Miss @IocBean ??
2017-09-02 11:54:17,202 org.nutz.ioc.loader.annotation.AnnotationIocLoader.<init>(AnnotationIocLoader.java:50) INFO  - Found 2 classes in 1 base-packages!
beans = ["userProfileModule", "userModule"]
2017-09-02 11:54:17,207 org.nutz.ioc.loader.json.JsonLoader.<init>(JsonLoader.java:40) DEBUG - Loaded 5 bean define from reader --
[txREPEATABLE_READ, txSERIALIZABLE, txNONE, txREAD_UNCOMMITTED, txREAD_COMMITTED]
2017-09-02 11:54:17,213 org.nutz.ioc.loader.combo.ComboIocLoader.createIocLoader(ComboIocLoader.java:118) DEBUG - found org.nutz.integration.quartz.QuartzIocLoader -- org.nutz.integration.quartz.QuartzIocLoader
2017-09-02 11:54:17,214 org.nutz.ioc.loader.json.JsonLoader.<init>(JsonLoader.java:56) DEBUG - Loaded 0 bean define from path=[] --> []
2017-09-02 11:54:17,225 org.nutz.ioc.impl.NutIoc.<init>(NutIoc.java:98) INFO  - NutIoc init begin ...
2017-09-02 11:54:17,232 org.nutz.ioc.impl.NutIoc.<init>(NutIoc.java:115) INFO  - ... NutIoc init complete
2017-09-02 11:54:17,240 org.nutz.mvc.impl.NutLoading.evalUrlMapping(NutLoading.java:159) INFO  - Build URL mapping by org.nutz.mvc.impl.UrlMappingImpl ...
2017-09-02 11:54:17,246 org.nutz.mvc.impl.NutLoading.createViewMakers(NutLoading.java:369) DEBUG - @Views(DefaultViewMaker.class)
2017-09-02 11:54:17,268 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 1 resource by src( mvc/nutzbook-mvc-chain.js ) , regex( ^(.+[.])(js|json)$ )
2017-09-02 11:54:17,286 org.nutz.mvc.impl.chainconfig.JsonActionChainMakerConfiguretion.<init>(JsonActionChainMakerConfiguretion.java:37) DEBUG - ActionChain Config:
{
   "default": {
      "ps": ["net.wendal.nutzbook.mvc.LogTimeProcessor", "org.nutz.mvc.impl.processor.UpdateRequestAttributesProcessor", "org.nutz.mvc.impl.processor.EncodingProcessor", "org.nutz.mvc.impl.processor.ModuleProcessor", "!org.nutz.integration.shiro.NutShiroProcessor", "org.nutz.mvc.impl.processor.ActionFiltersProcessor", "org.nutz.mvc.impl.processor.AdaptorProcessor", "org.nutz.mvc.impl.processor.MethodInvokeProcessor", "org.nutz.mvc.impl.processor.ViewProcessor"],
      "error": "org.nutz.mvc.impl.processor.FailProcessor"
   }
}
2017-09-02 11:54:17,287 org.nutz.mvc.impl.NutLoading.createChainMaker(NutLoading.java:266) DEBUG - @ChainBy(org.nutz.mvc.impl.NutActionChainMaker)
2017-09-02 11:54:17,299 org.nutz.mvc.impl.Loadings.scanModules(Loadings.java:154) DEBUG - module class location 'file:/E:/eclipsework/.metadata/.plugins/org.eclipse.wst.server.core/tmp0/wtpwebapps/nutzbook/WEB-INF/classes/'
2017-09-02 11:54:17,300 org.nutz.mvc.impl.Loadings.scanModuleInPackage(Loadings.java:184) DEBUG -  > scan 'net.wendal.nutzbook'
2017-09-02 11:54:17,313 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 12 resource by src( net/wendal/nutzbook/ ) , regex( ^.+[.]class$ )
2017-09-02 11:54:17,315 org.nutz.mvc.impl.Loadings.checkModule(Loadings.java:198) DEBUG -    >> add 'net.wendal.nutzbook.module.UserModule'
2017-09-02 11:54:17,315 org.nutz.mvc.impl.Loadings.checkModule(Loadings.java:198) DEBUG -    >> add 'net.wendal.nutzbook.module.UserProfileModule'
2017-09-02 11:54:17,432 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/'            >> (UserProfileModule.java:140).index    : UserProfile | @Ok(jsp:jsp.user.profile) @Fail(jsp:jsp.500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2017-09-02 11:54:17,437 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/get'         >> (UserProfileModule.java:52).get       : UserProfile | @Ok(json:full) @Fail(jsp:jsp.500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2017-09-02 11:54:17,447 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/update'      >> (UserProfileModule.java:67).update    : void       | @Ok(void ) @Fail(jsp:jsp.500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2017-09-02 11:54:17,453 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/active/mail' >> (UserProfileModule.java:174).activeMailCallback : String     | @Ok(raw  ) @Fail(jsp:jsp.500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2017-09-02 11:54:17,465 org.nutz.filepool.NutFilePool.<init>(NutFilePool.java:23) INFO  - Init file-pool by: E:/eclipsework/.metadata/.plugins/org.eclipse.wst.server.core/tmp0/wtpwebapps/nutzbook/WEB-INF/tmp/user_avatar [20000]
2017-09-02 11:54:17,469 org.nutz.filepool.NutFilePool.<init>(NutFilePool.java:37) DEBUG - file-pool.home: 'E:\eclipsework\.metadata\.plugins\org.eclipse.wst.server.core\tmp0\wtpwebapps\nutzbook\WEB-INF\tmp\user_avatar'
2017-09-02 11:54:17,475 org.nutz.filepool.NutFilePool.<init>(NutFilePool.java:66) INFO  - file-pool.cursor: 3
2017-09-02 11:54:17,486 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/avatar'      >> (UserProfileModule.java:98).uploadAvatar : void       | @Ok(>>:/user/profile) @Fail(jsp:jsp.500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2017-09-02 11:54:17,489 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/avatar'      >> (UserProfileModule.java:128).readAvatar : Object     | @Ok(raw:jpg) @Fail(jsp:jsp.500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2017-09-02 11:54:17,491 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/active/mail' >> (UserProfileModule.java:147).activeMail : Object     | @Ok(json:full) @Fail(jsp:jsp.500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2017-09-02 11:54:17,513 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/'                    >> (UserModule.java:150).index           : void       | @Ok(jsp:jsp.user.list) @Fail(http:500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2017-09-02 11:54:17,538 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/add'                 >> (UserModule.java:92).add              : Object     | @Ok(json:{locked:'password|salt',ignoreNull:true}) @Fail(http:500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2017-09-02 11:54:17,543 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/count'               >> (UserModule.java:38).count            : int        | @Ok(json:{locked:'password|salt',ignoreNull:true}) @Fail(http:500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2017-09-02 11:54:17,549 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/update'              >> (UserModule.java:105).update          : Object     | @Ok(json:{locked:'password|salt',ignoreNull:true}) @Fail(http:500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2017-09-02 11:54:17,553 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/delete'              >> (UserModule.java:129).delete          : Object     | @Ok(json:{locked:'password|salt',ignoreNull:true}) @Fail(http:500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2017-09-02 11:54:17,557 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/query'               >> (UserModule.java:139).query           : Object     | @Ok(json:{locked:'password|salt',ignoreNull:true}) @Fail(http:500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2017-09-02 11:54:17,563 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/login'               >> (UserModule.java:44).login            : Object     | @Ok(json:{locked:'password|salt',ignoreNull:true}) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2017-09-02 11:54:17,567 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/logout'              >> (UserModule.java:56).logout           : void       | @Ok(>>:/ ) @Fail(http:500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2017-09-02 11:54:17,568 org.nutz.mvc.impl.NutLoading.evalUrlMapping(NutLoading.java:220) INFO  - Found 15 module methods
2017-09-02 11:54:17,568 org.nutz.mvc.impl.NutLoading.evalLocalization(NutLoading.java:306) DEBUG - Localization: org.nutz.mvc.impl.NutMessageLoader('msg/')  dft<zh-CN>
2017-09-02 11:54:17,574 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 1 resource by src( msg/ ) , regex( ^.+[.]properties$ )
2017-09-02 11:54:17,574 org.nutz.mvc.impl.NutMessageLoader.load(NutMessageLoader.java:27) DEBUG - Load Messages in 1 resource : [[NutResource[zh-CN/user.properties]]]
2017-09-02 11:54:17,577 org.nutz.mvc.impl.NutMessageLoader.load(NutMessageLoader.java:95) DEBUG - Message Loaded, size = 2
2017-09-02 11:54:17,582 org.nutz.mvc.impl.NutLoading.evalSetup(NutLoading.java:274) INFO  - Setup application...
2017-09-02 11:54:17,582 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'dao'<interface org.nutz.dao.Dao>
2017-09-02 11:54:17,586 org.nutz.ioc.aop.SimpleAopMaker.<init>(SimpleAopMaker.java:79) DEBUG - Load AopConfigure for anno=org.nutz.ioc.aop.Aop by type=org.nutz.ioc.aop.config.impl.AnnotationAopConfigration
2017-09-02 11:54:17,588 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=dao
2017-09-02 11:54:17,591 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=dao
2017-09-02 11:54:17,613 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:169) DEBUG - Found IocObject(dao) in JsonLoader(paths=[ioc/])
2017-09-02 11:54:17,614 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'dao'<interface org.nutz.dao.Dao>
2017-09-02 11:54:17,643 org.nutz.ioc.aop.impl.DefaultMirrorFactory.getMirror(DefaultMirrorFactory.java:70) DEBUG - Load class org.nutz.dao.impl.NutDao without AOP
2017-09-02 11:54:17,645 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'dao' to [app] 
2017-09-02 11:54:17,651 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'dataSource'<>
2017-09-02 11:54:17,652 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=dataSource
2017-09-02 11:54:17,652 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=dataSource
2017-09-02 11:54:17,871 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:169) DEBUG - Found IocObject(dataSource) in JsonLoader(paths=[ioc/])
2017-09-02 11:54:17,872 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'dataSource'<>
2017-09-02 11:54:17,936 org.nutz.ioc.aop.impl.DefaultMirrorFactory.getMirror(DefaultMirrorFactory.java:70) DEBUG - Load class com.alibaba.druid.pool.DruidDataSource without AOP
2017-09-02 11:54:17,937 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'dataSource' to [app] 
2017-09-02 11:54:17,942 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'conf'<>
2017-09-02 11:54:17,943 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=conf
2017-09-02 11:54:17,948 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=conf
2017-09-02 11:54:17,949 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:169) DEBUG - Found IocObject(conf) in JsonLoader(paths=[ioc/])
2017-09-02 11:54:17,950 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'conf'<>
2017-09-02 11:54:17,951 org.nutz.ioc.aop.impl.DefaultMirrorFactory.getMirror(DefaultMirrorFactory.java:70) DEBUG - Load class org.nutz.ioc.impl.PropertiesProxy without AOP
2017-09-02 11:54:17,952 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'conf' to [app] 
2017-09-02 11:54:17,970 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 2 resource by src( custom/ ) , regex( ^.+[.]properties$ )
2017-09-02 11:54:18,157 com.alibaba.druid.pool.DruidDataSource.init(DruidDataSource.java:715) INFO  - {dataSource-1} inited
2017-09-02 11:54:18,159 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'dataSource'<>
2017-09-02 11:54:18,235 org.nutz.filepool.NutFilePool.<init>(NutFilePool.java:23) INFO  - Init file-pool by: C:\Users\Administrator/.nutz/tmp/dao/ [200000]
2017-09-02 11:54:18,236 org.nutz.filepool.NutFilePool.<init>(NutFilePool.java:37) DEBUG - file-pool.home: 'C:\Users\Administrator\.nutz\tmp\dao'
2017-09-02 11:54:18,237 org.nutz.filepool.NutFilePool.<init>(NutFilePool.java:66) INFO  - file-pool.cursor: 0
2017-09-02 11:54:18,258 org.nutz.dao.jdbc.Jdbcs.<clinit>(Jdbcs.java:90) DEBUG - Jdbcs init complete
2017-09-02 11:54:18,258 org.nutz.dao.jdbc.Jdbcs.getExpert(Jdbcs.java:103) INFO  - Get Connection from DataSource for JdbcExpert, if you lock at here, check your database server and configure
2017-09-02 11:54:18,889 org.nutz.dao.impl.DaoSupport.setDataSource(DaoSupport.java:188) DEBUG - select expert : org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert
2017-09-02 11:54:18,903 org.nutz.dao.impl.DaoSupport$1.invoke(DaoSupport.java:199) DEBUG - JDBC Driver --> mysql-connector-java-5.1.40 ( Revision: 402933ef52cad9aa82624e80acbea46e3a701ce6 )
2017-09-02 11:54:18,904 org.nutz.dao.impl.DaoSupport$1.invoke(DaoSupport.java:200) DEBUG - JDBC Name   --> MySQL Connector Java
2017-09-02 11:54:18,904 org.nutz.dao.impl.DaoSupport$1.invoke(DaoSupport.java:202) DEBUG - JDBC URL    --> jdbc:mysql://127.0.0.1:3306/nutzbook
2017-09-02 11:54:19,145 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:212) DEBUG - Mysql : character_set_client=gbk
2017-09-02 11:54:19,146 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:212) DEBUG - Mysql : character_set_connection=gbk
2017-09-02 11:54:19,147 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:212) DEBUG - Mysql : character_set_database=gbk
2017-09-02 11:54:19,147 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:212) DEBUG - Mysql : character_set_filesystem=binary
2017-09-02 11:54:19,148 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:212) DEBUG - Mysql : character_set_results=
2017-09-02 11:54:19,151 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:212) DEBUG - Mysql : character_set_server=gbk
2017-09-02 11:54:19,153 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:212) DEBUG - Mysql : character_set_system=utf8
2017-09-02 11:54:19,154 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:212) DEBUG - Mysql : character_sets_dir=D:\php-mysql\share\charsets\
2017-09-02 11:54:19,157 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:219) DEBUG - Mysql : binlog_format=STATEMENT
2017-09-02 11:54:19,163 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:226) DEBUG - Mysql : database=nutzbook
2017-09-02 11:54:19,165 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:232) DEBUG - Mysql : user=root@localhost
2017-09-02 11:54:19,283 org.nutz.dao.impl.DaoSupport.setDataSource(DaoSupport.java:221) DEBUG - Database info --> MYSQL:[MySQL - 5.5.33]
2017-09-02 11:54:19,304 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 12 resource by src( net/wendal/nutzbook/ ) , regex( ^.+[.]class$ )
2017-09-02 11:54:19,495 org.nutz.dao.impl.sql.run.NutDaoExecutor.printSQL(NutDaoExecutor.java:388) DEBUG - SELECT COUNT(*) FROM t_user 
2017-09-02 11:54:19,500 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'nutQuartzCronJobFactory'<class org.nutz.integration.quartz.NutQuartzCronJobFactory>
2017-09-02 11:54:19,500 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=nutQuartzCronJobFactory
2017-09-02 11:54:19,500 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=nutQuartzCronJobFactory
2017-09-02 11:54:19,501 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:169) DEBUG - Found IocObject(nutQuartzCronJobFactory) in QuartzIocLoader@1652825591
2017-09-02 11:54:19,502 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'nutQuartzCronJobFactory'<class org.nutz.integration.quartz.NutQuartzCronJobFactory>
2017-09-02 11:54:19,505 org.nutz.ioc.aop.impl.DefaultMirrorFactory.getMirror(DefaultMirrorFactory.java:70) DEBUG - Load class org.nutz.integration.quartz.NutQuartzCronJobFactory without AOP
2017-09-02 11:54:19,505 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'nutQuartzCronJobFactory' to [app] 
2017-09-02 11:54:19,509 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'scheduler'<>
2017-09-02 11:54:19,509 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=scheduler
2017-09-02 11:54:19,509 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=scheduler
2017-09-02 11:54:19,510 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:169) DEBUG - Found IocObject(scheduler) in QuartzIocLoader@1652825591
2017-09-02 11:54:19,510 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'scheduler'<>
2017-09-02 11:54:19,511 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'scheduler' to [app] 
2017-09-02 11:54:19,628 org.quartz.impl.StdSchedulerFactory.instantiate(StdSchedulerFactory.java:1172) INFO  - Using default implementation for ThreadExecutor
2017-09-02 11:54:19,671 org.quartz.core.SchedulerSignalerImpl.<init>(SchedulerSignalerImpl.java:61) INFO  - Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
2017-09-02 11:54:19,671 org.quartz.core.QuartzScheduler.<init>(QuartzScheduler.java:240) INFO  - Quartz Scheduler v.2.2.3 created.
2017-09-02 11:54:19,674 org.quartz.simpl.RAMJobStore.initialize(RAMJobStore.java:155) INFO  - RAMJobStore initialized.
2017-09-02 11:54:19,675 org.quartz.core.QuartzScheduler.initialize(QuartzScheduler.java:305) INFO  - Scheduler meta-data: Quartz Scheduler (v2.2.3) 'NutzbookScheduler' with instanceId 'NON_CLUSTERED'
  Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally.
  NOT STARTED.
  Currently in standby mode.
  Number of jobs executed: 0
  Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 3 threads.
  Using job-store 'org.quartz.simpl.RAMJobStore' - which does not support persistence. and is not clustered.

2017-09-02 11:54:19,676 org.quartz.impl.StdSchedulerFactory.instantiate(StdSchedulerFactory.java:1327) INFO  - Quartz scheduler 'NutzbookScheduler' initialized from default resource file in Quartz package: 'quartz.properties'
2017-09-02 11:54:19,676 org.quartz.impl.StdSchedulerFactory.instantiate(StdSchedulerFactory.java:1331) INFO  - Quartz scheduler version: 2.2.3
2017-09-02 11:54:19,677 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'jobFactory'<>
2017-09-02 11:54:19,677 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=jobFactory
2017-09-02 11:54:19,677 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=jobFactory
2017-09-02 11:54:19,679 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:169) DEBUG - Found IocObject(jobFactory) in QuartzIocLoader@1652825591
2017-09-02 11:54:19,679 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'jobFactory'<>
2017-09-02 11:54:19,682 org.nutz.ioc.aop.impl.DefaultMirrorFactory.getMirror(DefaultMirrorFactory.java:70) DEBUG - Load class org.nutz.integration.quartz.NutQuartzJobFactory without AOP
2017-09-02 11:54:19,682 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'jobFactory' to [app] 
2017-09-02 11:54:19,684 org.quartz.core.QuartzScheduler.setJobFactory(QuartzScheduler.java:2311) INFO  - JobFactory set to: org.nutz.integration.quartz.NutQuartzJobFactory@7bd36b45
2017-09-02 11:54:19,684 org.quartz.core.QuartzScheduler.start(QuartzScheduler.java:575) INFO  - Scheduler NutzbookScheduler_$_NON_CLUSTERED started.
2017-09-02 11:54:19,685 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'conf'<>
2017-09-02 11:54:19,686 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'htmlEmail'<class org.apache.commons.mail.HtmlEmail>
2017-09-02 11:54:19,686 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=htmlEmail
2017-09-02 11:54:19,686 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=htmlEmail
2017-09-02 11:54:19,688 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:169) DEBUG - Found IocObject(htmlEmail) in JsonLoader(paths=[ioc/])
2017-09-02 11:54:19,689 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'htmlEmail'<class org.apache.commons.mail.HtmlEmail>
2017-09-02 11:54:19,720 org.nutz.ioc.aop.impl.DefaultMirrorFactory.getMirror(DefaultMirrorFactory.java:70) DEBUG - Load class org.apache.commons.mail.ImageHtmlEmail without AOP
2017-09-02 11:54:19,750 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'conf'<>
2017-09-02 11:54:19,750 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'conf'<>
2017-09-02 11:54:19,751 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'emailAuthenticator'<>
2017-09-02 11:54:19,751 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=emailAuthenticator
2017-09-02 11:54:19,752 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=emailAuthenticator
2017-09-02 11:54:19,752 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:169) DEBUG - Found IocObject(emailAuthenticator) in JsonLoader(paths=[ioc/])
2017-09-02 11:54:19,753 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'emailAuthenticator'<>
2017-09-02 11:54:19,755 org.nutz.ioc.aop.impl.DefaultMirrorFactory.getMirror(DefaultMirrorFactory.java:70) DEBUG - Load class org.apache.commons.mail.DefaultAuthenticator without AOP
2017-09-02 11:54:19,755 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'emailAuthenticator' to [app] 
2017-09-02 11:54:19,756 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'conf'<>
2017-09-02 11:54:19,757 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'conf'<>
2017-09-02 11:54:19,760 org.quartz.core.QuartzSchedulerThread.run(QuartzSchedulerThread.java:276) DEBUG - batch acquisition of 0 triggers
2017-09-02 11:54:19,761 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'conf'<>
2017-09-02 11:54:19,762 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'conf'<>
2017-09-02 11:54:19,763 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'conf'<>
2017-09-02 11:54:19,763 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'conf'<>
2017-09-02 11:54:19,790 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'conf'<>
2017-09-02 11:54:20,303 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:141) INFO  - Nutz.Mvc[nutz] is up in 3320ms
2017-09-02 11:54:20,304 org.nutz.mvc.NutFilter._init(NutFilter.java:113) INFO  - exclusionsPrefix  = ^(/rs/|/druid/)
org.apache.commons.mail.EmailException: Sending the email to the following server failed : smtp.aliyun.com:25
	at org.apache.commons.mail.Email.sendMimeMessage(Email.java:1410)
	at net.wendal.nutzbook.MainSetup.init(MainSetup.java:46)
	at org.nutz.mvc.impl.NutLoading.evalSetup(NutLoading.java:277)
	at org.nutz.mvc.impl.NutLoading.load(NutLoading.java:121)
	at org.nutz.mvc.ActionHandler.<init>(ActionHandler.java:19)
	at org.nutz.mvc.NutFilter._init(NutFilter.java:87)
	at org.nutz.mvc.NutFilter.init(NutFilter.java:65)
	at org.apache.catalina.core.ApplicationFilterConfig.initFilter(ApplicationFilterConfig.java:279)
	at org.apache.catalina.core.ApplicationFilterConfig.getFilter(ApplicationFilterConfig.java:260)
	at org.apache.catalina.core.ApplicationFilterConfig.<init>(ApplicationFilterConfig.java:105)
	at org.apache.catalina.core.StandardContext.filterStart(StandardContext.java:4563)
	at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5205)
	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
	at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1419)
	at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1409)
	at java.util.concurrent.FutureTask.run(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at java.lang.Thread.run(Unknown Source)
Caused by: javax.mail.AuthenticationFailedException: 526 Authentication failure[0]

	at com.sun.mail.smtp.SMTPTransport$Authenticator.authenticate(SMTPTransport.java:892)
	at com.sun.mail.smtp.SMTPTransport.authenticate(SMTPTransport.java:814)
	at com.sun.mail.smtp.SMTPTransport.protocolConnect(SMTPTransport.java:728)
	at javax.mail.Service.connect(Service.java:386)
	at javax.mail.Service.connect(Service.java:245)
	at javax.mail.Service.connect(Service.java:194)
	at javax.mail.Transport.send0(Transport.java:253)
	at javax.mail.Transport.send(Transport.java:124)
	at org.apache.commons.mail.Email.sendMimeMessage(Email.java:1400)
	... 18 more
九月 02, 2017 11:54:20 上午 org.apache.coyote.AbstractProtocol start
信息: Starting ProtocolHandler [http-nio-8080]
九月 02, 2017 11:54:20 上午 org.apache.coyote.AbstractProtocol start
信息: Starting ProtocolHandler [ajp-nio-8009]
九月 02, 2017 11:54:20 上午 org.apache.catalina.startup.Catalina start
信息: Server startup in 7756 ms
2017-09-02 11:54:49,252 org.quartz.core.QuartzSchedulerThread.run(QuartzSchedulerThread.java:276) DEBUG - batch acquisition of 0 triggers
2017-09-02 11:55:13,951 org.quartz.core.QuartzSchedulerThread.run(QuartzSchedulerThread.java:276) DEBUG - batch acquisition of 0 triggers
2017-09-02 11:55:16,135 org.nutz.mvc.impl.UrlMappingImpl.get(UrlMappingImpl.java:101) DEBUG - Found mapping for [POST] path=/user/login : UserModule.login(UserModule.java:44)
2017-09-02 11:55:16,138 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'userModule'<class net.wendal.nutzbook.module.UserModule>
2017-09-02 11:55:16,139 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=userModule
2017-09-02 11:55:16,139 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:169) DEBUG - Found IocObject(userModule) in AnnotationIocLoader(packages=[net.wendal.nutzbook])
2017-09-02 11:55:16,140 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'userModule'<class net.wendal.nutzbook.module.UserModule>
2017-09-02 11:55:16,141 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'txREAD_COMMITTED'<interface org.nutz.aop.MethodInterceptor>
2017-09-02 11:55:16,141 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=txREAD_COMMITTED
2017-09-02 11:55:16,142 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=txREAD_COMMITTED
2017-09-02 11:55:16,144 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:169) DEBUG - Found IocObject(txREAD_COMMITTED) in TransIocLoader@139932550
2017-09-02 11:55:16,144 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'txREAD_COMMITTED'<interface org.nutz.aop.MethodInterceptor>
2017-09-02 11:55:16,144 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'txREAD_COMMITTED' to [app] 
2017-09-02 11:55:16,154 org.nutz.aop.asm.AsmClassAgent.<clinit>(AsmClassAgent.java:29) DEBUG - AsmClassAgent will define class in Version 50
2017-09-02 11:55:16,173 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'userModule' to [app] 
2017-09-02 11:55:16,179 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'dao'<interface org.nutz.dao.Dao>
2017-09-02 11:55:16,182 org.nutz.ioc.val.ReferTypeValue.get(ReferTypeValue.java:64) DEBUG - name=emailService not found, search for type=net.wendal.nutzbook.service.EmailService
2017-09-02 11:55:16,183 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=conf
2017-09-02 11:55:16,184 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:169) DEBUG - Found IocObject(conf) in JsonLoader(paths=[ioc/])
2017-09-02 11:55:16,185 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=dao
2017-09-02 11:55:16,185 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:169) DEBUG - Found IocObject(dao) in JsonLoader(paths=[ioc/])
2017-09-02 11:55:16,186 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=emailAuthenticator
2017-09-02 11:55:16,186 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:169) DEBUG - Found IocObject(emailAuthenticator) in JsonLoader(paths=[ioc/])
2017-09-02 11:55:16,187 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=dataSource
2017-09-02 11:55:16,189 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:169) DEBUG - Found IocObject(dataSource) in JsonLoader(paths=[ioc/])
2017-09-02 11:55:16,189 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=htmlEmail
2017-09-02 11:55:16,190 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:169) DEBUG - Found IocObject(htmlEmail) in JsonLoader(paths=[ioc/])
2017-09-02 11:55:16,190 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:169) DEBUG - Found IocObject(userProfileModule) in AnnotationIocLoader(packages=[net.wendal.nutzbook])
2017-09-02 11:55:16,190 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:169) DEBUG - Found IocObject(userModule) in AnnotationIocLoader(packages=[net.wendal.nutzbook])
2017-09-02 11:55:16,191 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=txREPEATABLE_READ
2017-09-02 11:55:16,191 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:169) DEBUG - Found IocObject(txREPEATABLE_READ) in TransIocLoader@139932550
2017-09-02 11:55:16,191 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=txSERIALIZABLE
2017-09-02 11:55:16,192 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:169) DEBUG - Found IocObject(txSERIALIZABLE) in TransIocLoader@139932550
2017-09-02 11:55:16,192 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=txNONE
2017-09-02 11:55:16,193 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:169) DEBUG - Found IocObject(txNONE) in TransIocLoader@139932550
2017-09-02 11:55:16,193 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=txREAD_UNCOMMITTED
2017-09-02 11:55:16,193 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:169) DEBUG - Found IocObject(txREAD_UNCOMMITTED) in TransIocLoader@139932550
2017-09-02 11:55:16,194 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=txREAD_COMMITTED
2017-09-02 11:55:16,194 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:169) DEBUG - Found IocObject(txREAD_COMMITTED) in TransIocLoader@139932550
2017-09-02 11:55:16,195 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=scheduler
2017-09-02 11:55:16,195 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:169) DEBUG - Found IocObject(scheduler) in QuartzIocLoader@1652825591
2017-09-02 11:55:16,195 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=nutQuartzCronJobFactory
2017-09-02 11:55:16,196 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:169) DEBUG - Found IocObject(nutQuartzCronJobFactory) in QuartzIocLoader@1652825591
2017-09-02 11:55:16,196 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=jobFactory
2017-09-02 11:55:16,196 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:169) DEBUG - Found IocObject(jobFactory) in QuartzIocLoader@1652825591
2017-09-02 11:55:16,197 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=quartzManager
2017-09-02 11:55:16,199 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:169) DEBUG - Found IocObject(quartzManager) in QuartzIocLoader@1652825591
2017-09-02 11:55:16,200 org.nutz.ioc.impl.ScopeContext.remove(ScopeContext.java:84) DEBUG - Remove object 'userModule' from [app] 
2017-09-02 11:55:16,200 net.wendal.nutzbook.mvc.LogTimeProcessor.process(LogTimeProcessor.java:23) DEBUG - [POST]URI=/nutzbook/user/login 64ms
2017-09-02 11:55:16,202 org.nutz.mvc.impl.processor.FailProcessor.process(FailProcessor.java:28) WARN  - Error@/user/login :
org.nutz.ioc.IocException: [userModule, class:net.wendal.nutzbook.service.EmailService] # none ioc bean match class=net.wendal.nutzbook.service.EmailService
	at org.nutz.ioc.impl.NutIoc.getByType(NutIoc.java:399)
	at org.nutz.ioc.val.ReferTypeValue.get(ReferTypeValue.java:66)
	at org.nutz.ioc.weaver.FieldInjector.inject(FieldInjector.java:31)
	at org.nutz.ioc.weaver.DefaultWeaver.fill(DefaultWeaver.java:56)
	at org.nutz.ioc.impl.ObjectMakerImpl.make(ObjectMakerImpl.java:135)
	at org.nutz.ioc.impl.NutIoc.get(NutIoc.java:210)
	at org.nutz.ioc.impl.NutIoc.get(NutIoc.java:239)
	at org.nutz.mvc.impl.processor.ModuleProcessor.process(ModuleProcessor.java:116)
	at org.nutz.mvc.impl.processor.AbstractProcessor.doNext(AbstractProcessor.java:44)
	at org.nutz.mvc.impl.processor.EncodingProcessor.process(EncodingProcessor.java:27)
	at org.nutz.mvc.impl.processor.AbstractProcessor.doNext(AbstractProcessor.java:44)
	at org.nutz.mvc.impl.processor.UpdateRequestAttributesProcessor.process(UpdateRequestAttributesProcessor.java:15)
	at org.nutz.mvc.impl.processor.AbstractProcessor.doNext(AbstractProcessor.java:44)
	at net.wendal.nutzbook.mvc.LogTimeProcessor.process(LogTimeProcessor.java:18)
	at org.nutz.mvc.impl.NutActionChain.doChain(NutActionChain.java:44)
	at org.nutz.mvc.impl.ActionInvoker.invoke(ActionInvoker.java:67)
	at org.nutz.mvc.ActionHandler.handle(ActionHandler.java:31)
	at org.nutz.mvc.NutFilter.doFilter(NutFilter.java:198)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165)
	at com.alibaba.druid.support.http.WebStatFilter.doFilter(WebStatFilter.java:123)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165)
	at org.apache.shiro.web.servlet.AbstractShiroFilter.executeChain(AbstractShiroFilter.java:449)
	at org.apache.shiro.web.servlet.AbstractShiroFilter$1.call(AbstractShiroFilter.java:365)
	at org.apache.shiro.subject.support.SubjectCallable.doCall(SubjectCallable.java:90)
	at org.apache.shiro.subject.support.SubjectCallable.call(SubjectCallable.java:83)
	at org.apache.shiro.subject.support.DelegatingSubject.execute(DelegatingSubject.java:383)
	at org.apache.shiro.web.servlet.AbstractShiroFilter.doFilterInternal(AbstractShiroFilter.java:362)
	at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:474)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
	at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:624)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:349)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:495)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:767)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1347)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Unknown Source)

现在添加了邮箱的验证功能后，登录就报错了