@wendal

源码看了下，问题应该在shiro里

public int fetch(String username, String password) {
        User user = fetch(username);
        if (user == null) {
            return -1;
        }
        String _pass = new Sha256Hash(password, user.getSalt()).toHex();
        if(_pass.equalsIgnoreCase(user.getPassword())) {
            return user.getId();
        }
        return -1;
    }

new Sha256Hash 时 传入密码 跟salt 。默认用户得到的hash玛怎么跟我数据库里保存的hash玛不匹配呢？ 自己新增的用户new Sha256Hash得到的hash玛就数据库里的匹配成功。

@wendal w

package net.wendal.nutzbook;

import java.util.Date;

import net.wendal.nutzbook.bean.User;
import net.wendal.nutzbook.service.UserService;

import org.nutz.dao.Dao;
import org.nutz.dao.util.Daos;
import org.nutz.integration.quartz.NutQuartzCronJobFactory;
import org.nutz.ioc.Ioc;
import org.nutz.mvc.NutConfig;
import org.nutz.mvc.Setup;

public class MainSetup implements Setup {

  // 注意是init方法,不是destroy方法
    public void init(NutConfig nc) {
        Ioc ioc = nc.getIoc();
        Dao dao = ioc.get(Dao.class);
        Daos.migration(dao, User.class, true, true, false);
        // 如果提示没有createTablesInPackage方法,请确认用了最新版的nutz,且老版本的nutz已经删除干净
        Daos.createTablesInPackage(dao, "net.wendal.nutzbook", false);

        // 初始化默认根用户
        if (dao.count(User.class) == 0) {
            UserService us = ioc.get(UserService.class);
            us.add("admin", "123456");
        }
        // 获取NutQuartzCronJobFactory从而触发计划任务的初始化与启动
        ioc.get(NutQuartzCronJobFactory.class);
        
        // 测试发送邮件
     /*   try {
            HtmlEmail email = ioc.get(HtmlEmail.class);
            email.setSubject("测试NutzBook");
            email.setMsg("This is a test mail ... :-)" + System.currentTimeMillis());
            email.addTo("543357851@qq.com");//请务必改成自己的邮箱!!!
            email.buildMimeMessage();
            email.sendMimeMessage();
        } catch (Exception e) {
            e.printStackTrace();
        }
        */
    }

    public void destroy(NutConfig nc) {
         // webapp销毁之前执行的逻辑
         // 这个时候依然可以从nc取出ioc, 然后取出需要的ioc 对象进行操作
    }

}

初始化默认用户的问题吗？
@wendal

源码如下

package net.wendal.nutzbook.module;

import java.util.Date;

import javax.servlet.http.HttpSession;

import net.wendal.nutzbook.bean.User;
import net.wendal.nutzbook.bean.UserProfile;
import net.wendal.nutzbook.service.UserService;
import net.wendal.nutzbook.util.Toolkit;

import org.apache.shiro.SecurityUtils;
import org.apache.shiro.authz.annotation.RequiresUser;
import org.nutz.aop.interceptor.ioc.TransAop;
import org.nutz.dao.Cnd;
import org.nutz.dao.QueryResult;
import org.nutz.dao.pager.Pager;
import org.nutz.integration.shiro.SimpleShiroToken;
import org.nutz.ioc.aop.Aop;
import org.nutz.ioc.loader.annotation.Inject;
import org.nutz.ioc.loader.annotation.IocBean;
import org.nutz.lang.Strings;
import org.nutz.lang.util.NutMap;
import org.nutz.mvc.Scope;
import org.nutz.mvc.annotation.At;
import org.nutz.mvc.annotation.Attr;
import org.nutz.mvc.annotation.By;
import org.nutz.mvc.annotation.Fail;
import org.nutz.mvc.annotation.Filters;
import org.nutz.mvc.annotation.GET;
import org.nutz.mvc.annotation.Ok;
import org.nutz.mvc.annotation.POST;
import org.nutz.mvc.annotation.Param;
import org.nutz.mvc.filter.CheckSession;

@IocBean // 声明为Ioc容器中的一个Bean
@At("/user") // 整个模块的路径前缀
@Ok("json:{locked:'password|salt',ignoreNull:true}") // 忽略password和salt属性,忽略空属性的json输出
@Fail("http:500") // 抛出异常的话,就走500页面
public class UserModule extends BaseModule{

	 @Inject
	 protected UserService userService;
	 
    @At
    public int count() { // 统计用户数的方法,算是个测试点
        return dao.count(User.class);
    }

    @At
    @POST
    public Object login(@Param("username")String username, 
            @Param("password")String password, 
            @Param("captcha")String captcha,
            @Attr(scope=Scope.SESSION, value="nutz_captcha")String _captcha,
            HttpSession session) {
        NutMap re = new NutMap();
        if (!Toolkit.checkCaptcha(_captcha, captcha)) {
            return re.setv("ok", false).setv("msg", "验证码错误");
        }
        int userId = userService.fetch(username, password);
        if (userId < 0) {
            return re.setv("ok", false).setv("msg", "用户名或密码错误");
        } else {
            session.setAttribute("me", userId);
            // 完成nutdao_realm后启用.
           SecurityUtils.getSubject().login(new SimpleShiroToken(userId));
            return re.setv("ok", true);
        }
    }

    @At
    @Ok(">>:/user/") // 跟其他方法不同,这个方法完成后就跳转首页了
    public void logout(HttpSession session) {
        session.invalidate();
    }
   
    @At
    @RequiresUser
    public Object add(@Param("..")User user) { // 两个点号是按对象属性一一设置
        NutMap re = new NutMap();
        String msg = checkUser(user, true);
        if (msg != null){
            return re.setv("ok", false).setv("msg", msg);
        }
        user = userService.add(user.getName(), user.getPassword());
        return re.setv("ok", true).setv("data", user);
    }

    @At //修改
    @RequiresUser
    public Object update(@Param("password")String password, @Attr("me")int me) {
        if (Strings.isBlank(password) || password.length() < 6)
            return new NutMap().setv("ok", false).setv("msg", "密码不符合要求");
        userService.updatePassword(me, password);
        return new NutMap().setv("ok", true);
    }
    
    
    @At
    @Aop(TransAop.READ_COMMITTED)
    @RequiresUser
    public Object delete(@Param("id")int id, @Attr("me")int me) {
        if (me == id) {
            return new NutMap().setv("ok", false).setv("msg", "不能删除当前用户!!");
        }
        dao.delete(User.class, id); // 再严谨一些的话,需要判断是否为>0
        dao.clear(UserProfile.class, Cnd.where("userId", "=", me));
        return new NutMap().setv("ok", true);
    }

    @RequiresUser
    @At
    public Object query(@Param("name")String name, @Param("..")Pager pager) {
        Cnd cnd = Strings.isBlank(name)? null : Cnd.where("name", "like", "%"+name+"%");
        QueryResult qr = new QueryResult();
        qr.setList(dao.query(User.class, cnd, pager));
        pager.setRecordCount(dao.count(User.class, cnd));
        qr.setPager(pager);
        return qr; //默认分页是第1页,每页20条
    }

    @At("/")
    @RequiresUser
    @Ok("jsp:jsp.user.lonin") // 真实路径是 /WEB-INF/jsp/user/login.jsp
    public void index() {
    	
    }
    
    @GET
    @At("/login")
    @Ok("jsp:jsp.user.login") // 降内部重定向到登录jsp
    public void loginPage() {}
    protected String checkUser(User user, boolean create) {
        if (user == null) {
            return "空对象";
        }
        if (create) {
            if (Strings.isBlank(user.getName()) || Strings.isBlank(user.getPassword()))
                return "用户名/密码不能为空";
        } else {
            if (Strings.isBlank(user.getPassword()))
                return "密码不能为空";
        }
        String passwd = user.getPassword().trim();
        if (6 > passwd.length() || passwd.length() > 12) {
            return "密码长度错误";
        }
        user.setPassword(passwd);
        if (create) {
            int count = dao.count(User.class, Cnd.where("name", "=", user.getName()));
            if (count != 0) {
                return "用户名已经存在";
            }
        } else {
            if (user.getId() < 1) {
                return "用户Id非法";
            }
        }
        if (user.getName() != null)
            user.setName(user.getName().trim());
        return null;
    }
}

userService.java

package net.wendal.nutzbook.service;

import java.util.Date;

import net.wendal.nutzbook.bean.User;

import org.apache.shiro.crypto.hash.Sha256Hash;
import org.nutz.ioc.loader.annotation.IocBean;
import org.nutz.lang.random.R;
import org.nutz.service.IdNameEntityService;

@IocBean(fields="dao")
public class UserService extends IdNameEntityService<User> {

    public User add(String name, String password) {
        User user = new User();
        user.setName(name.trim());
        user.setSalt(R.UU16());
        user.setPassword(new Sha256Hash(password, user.getSalt()).toHex());
        user.setCreateTime(new Date());
        user.setUpdateTime(new Date());
        return dao().insert(user);
    }

    public int fetch(String username, String password) {
        User user = fetch(username);
        if (user == null) {
            return -1;
        }
        String _pass = new Sha256Hash(password, user.getSalt()).toHex();
        if(_pass.equalsIgnoreCase(user.getPassword())) {
            return user.getId();
        }
        return -1;
    }

    public void updatePassword(int userId, String password) {
        User user = fetch(userId);
        if (user == null) {
            return;
        }
        user.setSalt(R.UU16());
        user.setPassword(new Sha256Hash(password, user.getSalt()).toHex());
        user.setUpdateTime(new Date());
        dao().update(user, "^(password|salt|updateTime)$");
    }
}

不知道是不是权限的问题

SimpleAuthorizingRealm.java

package net.wendal.nutzbook.shiro.realm;

import org.apache.shiro.authc.AuthenticationException;
import org.apache.shiro.authc.AuthenticationInfo;
import org.apache.shiro.authc.AuthenticationToken;
import org.apache.shiro.authc.LockedAccountException;
import org.apache.shiro.authc.SimpleAccount;
import org.apache.shiro.authc.credential.CredentialsMatcher;
import org.apache.shiro.authz.AuthorizationException;
import org.apache.shiro.authz.AuthorizationInfo;
import org.apache.shiro.authz.SimpleAuthorizationInfo;
import org.apache.shiro.cache.CacheManager;
import org.apache.shiro.realm.AuthorizingRealm;
import org.apache.shiro.subject.PrincipalCollection;
import org.nutz.dao.Dao;
import org.nutz.integration.shiro.SimpleShiroToken;
import org.nutz.mvc.Mvcs;

import net.wendal.nutzbook.bean.Permission;
import net.wendal.nutzbook.bean.Role;
import net.wendal.nutzbook.bean.User;

public class SimpleAuthorizingRealm extends AuthorizingRealm {

    protected Dao dao; // ShiroFilter先于NutFilter初始化化,所以无法使用注入功能

    protected AuthorizationInfo doGetAuthorizationInfo(PrincipalCollection principals) {
        // null usernames are invalid
        if (principals == null) {
            throw new AuthorizationException("PrincipalCollection method argument cannot be null.");
        }
        int userId = (Integer) principals.getPrimaryPrincipal();
        User user = dao().fetch(User.class, userId);
        if (user == null)
            return null;
        if (user.isLocked())
            throw new LockedAccountException("Account [" + user.getName() + "] is locked.");

        SimpleAuthorizationInfo auth = new SimpleAuthorizationInfo();
        user = dao().fetchLinks(user, null);
        if (user.getRoles() != null) {
            dao().fetchLinks(user.getRoles(), null);
            for (Role role : user.getRoles()) {
                auth.addRole(role.getName());
                if (role.getPermissions() != null) {
                    for (Permission p : role.getPermissions()) {
                        auth.addStringPermission(p.getName());
                    }
                }
            }
        }
        if (user.getPermissions() != null) { // 特许/临时分配的权限
            for (Permission p : user.getPermissions()) {
                auth.addStringPermission(p.getName());
            }
        }
        return auth;
    }

    protected AuthenticationInfo doGetAuthenticationInfo(AuthenticationToken token) throws AuthenticationException {
        SimpleShiroToken upToken = (SimpleShiroToken) token;
        // upToken.getPrincipal() 的返回值就是SimpleShiroToken构造方法传入的值
        // 可以是int也可以是User类实例,或任何你希望的值,自行处理一下就好了
        User user = dao().fetch(User.class, ((Integer)upToken.getPrincipal()).longValue());
        if (user == null)
            return null;
        if (user.isLocked())
            throw new LockedAccountException("Account [" + user.getName() + "] is locked.");
        return new SimpleAccount(user.getId(), user.getPassword(), getName());
    }

    /**
     * 覆盖父类的验证,直接pass. 在shiro内做验证的话, 出错了都不知道哪里错
     */
    protected void assertCredentialsMatch(AuthenticationToken token, AuthenticationInfo info) throws AuthenticationException {
    }

    public SimpleAuthorizingRealm() {
        this(null, null);
    }

    public SimpleAuthorizingRealm(CacheManager cacheManager, CredentialsMatcher matcher) {
        super(cacheManager, matcher);
        setAuthenticationTokenClass(SimpleShiroToken.class); // 非常非常重要,与SecurityUtils.getSubject().login是对应关系!!!
    }

    public SimpleAuthorizingRealm(CacheManager cacheManager) {
        this(cacheManager, null);
    }

    public SimpleAuthorizingRealm(CredentialsMatcher matcher) {
        this(null, matcher);
    }

    public Dao dao() {
        if (dao == null) {
            dao = Mvcs.ctx().getDefaultIoc().get(Dao.class, "dao");
            return dao;
        }
        return dao;
    }

    public void setDao(Dao dao) {
        this.dao = dao;
    }

}

@wendal

@wendal 那请问我的问题出在何处呢？

是啊 我也就纳了闷了！！！

看方法 salt是通过查 name从数据库得到的 应该不会出问题.
问题可能在密码上 编码什么的会不会影响算法呢？

 String _pass = new Sha256Hash(password, user.getSalt()).toHex();
        if(_pass.equalsIgnoreCase(user.getPassword())) {
            return user.getId();
        }
        return -1;

问题就出现在这一段 debug看到—pass得到的跟数据库的就是不同
@wendal

@wendal 能上传图片吗 [苦笑不得]

请问怎么把参数打印到日志里呢？
@wendal

日志在最后；

2018-4-12 14:28:23 org.apache.catalina.startup.VersionLoggerListener log
信息: Server version:        Apache Tomcat/7.0.73
2018-4-12 14:28:23 org.apache.catalina.startup.VersionLoggerListener log
信息: Server built:          Nov 7 2016 21:27:23 UTC
2018-4-12 14:28:23 org.apache.catalina.startup.VersionLoggerListener log
信息: Server number:         7.0.73.0
2018-4-12 14:28:23 org.apache.catalina.startup.VersionLoggerListener log
信息: OS Name:               Windows Vista
2018-4-12 14:28:23 org.apache.catalina.startup.VersionLoggerListener log
信息: OS Version:            6.1
2018-4-12 14:28:23 org.apache.catalina.startup.VersionLoggerListener log
信息: Architecture:          amd64
2018-4-12 14:28:23 org.apache.catalina.startup.VersionLoggerListener log
信息: Java Home:             D:\myEclipse\Common\binary\com.sun.java.jdk.win32.x86_64_1.6.0.013\jre
2018-4-12 14:28:23 org.apache.catalina.startup.VersionLoggerListener log
信息: JVM Version:           1.6.0_13-b03
2018-4-12 14:28:23 org.apache.catalina.startup.VersionLoggerListener log
信息: JVM Vendor:            Sun Microsystems Inc.
2018-4-12 14:28:23 org.apache.catalina.startup.VersionLoggerListener log
信息: CATALINA_BASE:         E:/nutztomcat/tomcat/apache-tomcat-7.0.73
2018-4-12 14:28:23 org.apache.catalina.startup.VersionLoggerListener log
信息: CATALINA_HOME:         E:/nutztomcat/tomcat/apache-tomcat-7.0.73
2018-4-12 14:28:23 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Dcatalina.home=E:/nutztomcat/tomcat/apache-tomcat-7.0.73
2018-4-12 14:28:23 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Dcatalina.base=E:/nutztomcat/tomcat/apache-tomcat-7.0.73
2018-4-12 14:28:23 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Djava.endorsed.dirs=E:/nutztomcat/tomcat/apache-tomcat-7.0.73/common/endorsed
2018-4-12 14:28:23 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Djava.io.tmpdir=E:/nutztomcat/tomcat/apache-tomcat-7.0.73/temp
2018-4-12 14:28:23 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Djava.library.path=D:/myEclipse/Common/binary/com.sun.java.jdk.win32.x86_64_1.6.0.013/bin;E:/nutztomcat/tomcat/apache-tomcat-7.0.73/bin
2018-4-12 14:28:23 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Dsun.io.useCanonCaches=false
2018-4-12 14:28:23 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Dfile.encoding=UTF-8
2018-4-12 14:28:23 org.apache.catalina.core.AprLifecycleListener lifecycleEvent
信息: Loaded APR based Apache Tomcat Native library 1.2.10 using APR version 1.5.2.
2018-4-12 14:28:23 org.apache.catalina.core.AprLifecycleListener lifecycleEvent
信息: APR capabilities: IPv6 [true], sendfile [true], accept filters [false], random [true].
2018-4-12 14:28:23 org.apache.catalina.core.AprLifecycleListener initializeSSL
信息: OpenSSL successfully initialized (OpenSSL 1.0.2j  26 Sep 2016)
2018-4-12 14:28:23 org.apache.coyote.AbstractProtocol init
信息: Initializing ProtocolHandler ["http-apr-8080"]
2018-4-12 14:28:23 org.apache.coyote.AbstractProtocol init
信息: Initializing ProtocolHandler ["ajp-apr-8009"]
2018-4-12 14:28:23 org.apache.catalina.startup.Catalina load
信息: Initialization processed in 963 ms
2018-4-12 14:28:23 org.apache.catalina.core.StandardService startInternal
信息: Starting service Catalina
2018-4-12 14:28:23 org.apache.catalina.core.StandardEngine startInternal
信息: Starting Servlet Engine: Apache Tomcat/7.0.73
2018-4-12 14:28:23 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deploying web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\docs
2018-4-12 14:28:24 org.apache.tomcat.websocket.server.WsSci onStartup
信息: JSR 356 WebSocket (Java WebSocket 1.1) support is not available when running on Java 6. To suppress this message, run Tomcat on Java 7, remove the WebSocket JARs from $CATALINA_HOME/lib or add the WebSocket JARs to the tomcat.util.scan.DefaultJarScanner.jarsToSkip property in $CATALINA_BASE/conf/catalina.properties. Note that the deprecated Tomcat 7 WebSocket API will be available. 
2018-4-12 14:28:24 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deployment of web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\docs has finished in 366 ms
2018-4-12 14:28:24 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deploying web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\examples
2018-4-12 14:28:24 org.apache.catalina.core.ApplicationContext log
信息: ContextListener: contextInitialized()
2018-4-12 14:28:24 org.apache.catalina.core.ApplicationContext log
信息: SessionListener: contextInitialized()
2018-4-12 14:28:24 org.apache.catalina.core.ApplicationContext log
信息: ContextListener: attributeAdded('org.apache.jasper.compiler.TldLocationsCache', 'org.apache.jasper.compiler.TldLocationsCache@10ed32c4')
2018-4-12 14:28:24 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deployment of web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\examples has finished in 313 ms
2018-4-12 14:28:24 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deploying web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\host-manager
2018-4-12 14:28:24 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deployment of web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\host-manager has finished in 63 ms
2018-4-12 14:28:24 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deploying web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\manager
2018-4-12 14:28:24 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deployment of web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\manager has finished in 47 ms
2018-4-12 14:28:24 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deploying web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\nutzbook
2018-4-12 14:28:25 org.apache.catalina.startup.TaglibUriRule body
信息: TLD skipped. URI: http://java.sun.com/jstl/core is already defined
2018-4-12 14:28:25 org.apache.catalina.startup.TaglibUriRule body
信息: TLD skipped. URI: http://java.sun.com/jstl/fmt is already defined
2018-4-12 14:28:25 org.apache.catalina.startup.TaglibUriRule body
信息: TLD skipped. URI: http://java.sun.com/jstl/sql is already defined
2018-4-12 14:28:25 org.apache.catalina.startup.TaglibUriRule body
信息: TLD skipped. URI: http://java.sun.com/jstl/xml is already defined
2018-4-12 14:28:25 org.apache.catalina.startup.TldConfig execute
信息: 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.
2018-4-12 14:28:25 org.apache.catalina.core.ApplicationContext log
信息: Initializing Shiro environment
2018-04-12 14:28:25,997 org.apache.shiro.web.env.EnvironmentLoader.initEnvironment(EnvironmentLoader.java:128) INFO  - Starting Shiro environment initialization.
2018-04-12 14:28:26,021 org.apache.shiro.web.env.IniWebEnvironment.init(IniWebEnvironment.java:76) DEBUG - Checking any specified config locations.
2018-04-12 14:28:26,022 org.apache.shiro.web.env.IniWebEnvironment.init(IniWebEnvironment.java:81) DEBUG - No INI instance or config locations specified.  Trying default config locations.
2018-04-12 14:28:26,028 org.apache.shiro.io.ResourceUtils.loadFromClassPath(ResourceUtils.java:159) DEBUG - Opening resource from class path [shiro.ini]
2018-04-12 14:28:26,033 org.apache.shiro.config.Ini.load(Ini.java:351) DEBUG - Parsing [main]
2018-04-12 14:28:26,036 org.apache.shiro.config.Ini.load(Ini.java:351) DEBUG - Parsing [urls]
2018-04-12 14:28:26,038 org.apache.shiro.web.env.IniWebEnvironment.getDefaultIni(IniWebEnvironment.java:136) DEBUG - Discovered non-empty INI configuration at location 'classpath:shiro.ini'.  Using for configuration.
2018-04-12 14:28:26,044 org.apache.shiro.config.IniFactorySupport.createInstance(IniFactorySupport.java:122) DEBUG - Creating instance from Ini [sections=main,urls]
2018-04-12 14:28:26,337 org.apache.shiro.realm.AuthorizingRealm.getAuthorizationCacheLazy(AuthorizingRealm.java:234) DEBUG - No authorizationCache instance set.  Checking for a cacheManager...
2018-04-12 14:28:26,337 org.apache.shiro.realm.AuthorizingRealm.getAuthorizationCacheLazy(AuthorizingRealm.java:248) DEBUG - No cache or cacheManager properties have been set.  Authorization cache cannot be obtained.
2018-04-12 14:28:26,337 org.apache.shiro.config.ReflectionBuilder.createNewInstance(ReflectionBuilder.java:296) INFO  - An instance with name 'authc' already exists.  Redefining this object as a new instance of type org.nutz.integration.shiro.SimpleAuthenticationFilter
2018-04-12 14:28:26,368 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: false
2018-04-12 14:28:26,368 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Boolean' value 'false' to type 'Boolean'
2018-04-12 14:28:26,368 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a Boolean
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: 0
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Integer' value '0' to type 'Byte'
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:171) DEBUG -     Converted to Byte value '0'
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value:  
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Character' value ' ' to type 'Character'
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a Character
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: 0
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Integer' value '0' to type 'Double'
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:171) DEBUG -     Converted to Double value '0.0'
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: 0
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Integer' value '0' to type 'Float'
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:171) DEBUG -     Converted to Float value '0.0'
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: 0
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Integer' value '0' to type 'Integer'
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a Integer
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: 0
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Integer' value '0' to type 'Long'
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:171) DEBUG -     Converted to Long value '0'
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: 0
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Integer' value '0' to type 'Short'
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:171) DEBUG -     Converted to Short value '0'
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: 0.0
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'BigDecimal' value '0.0' to type 'BigDecimal'
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a BigDecimal
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: 0
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'BigInteger' value '0' to type 'BigInteger'
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a BigInteger
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: false
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Boolean' value 'false' to type 'Boolean'
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a Boolean
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: 0
2018-04-12 14:28:26,384 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Integer' value '0' to type 'Byte'
2018-04-12 14:28:26,400 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:171) DEBUG -     Converted to Byte value '0'
2018-04-12 14:28:26,400 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value:  
2018-04-12 14:28:26,400 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Character' value ' ' to type 'Character'
2018-04-12 14:28:26,401 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a Character
2018-04-12 14:28:26,401 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: 0
2018-04-12 14:28:26,401 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Integer' value '0' to type 'Double'
2018-04-12 14:28:26,402 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:171) DEBUG -     Converted to Double value '0.0'
2018-04-12 14:28:26,402 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: 0
2018-04-12 14:28:26,402 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Integer' value '0' to type 'Float'
2018-04-12 14:28:26,402 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:171) DEBUG -     Converted to Float value '0.0'
2018-04-12 14:28:26,403 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: 0
2018-04-12 14:28:26,403 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Integer' value '0' to type 'Integer'
2018-04-12 14:28:26,403 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a Integer
2018-04-12 14:28:26,403 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: 0
2018-04-12 14:28:26,404 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Integer' value '0' to type 'Long'
2018-04-12 14:28:26,404 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:171) DEBUG -     Converted to Long value '0'
2018-04-12 14:28:26,404 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: 0
2018-04-12 14:28:26,404 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Integer' value '0' to type 'Short'
2018-04-12 14:28:26,404 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:171) DEBUG -     Converted to Short value '0'
2018-04-12 14:28:26,404 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: 
2018-04-12 14:28:26,404 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'String' value '' to type 'String'
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [Z@6e878f8f
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'boolean[]' value '[Z@6e878f8f' to type 'boolean[]'
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a boolean[]
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [B@5e22dfa
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'byte[]' value '[B@5e22dfa' to type 'byte[]'
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a byte[]
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [C@44387b1a
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'char[]' value '[C@44387b1a' to type 'char[]'
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a char[]
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [D@581a0af3
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'double[]' value '[D@581a0af3' to type 'double[]'
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a double[]
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [F@15c504b5
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'float[]' value '[F@15c504b5' to type 'float[]'
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a float[]
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [I@39b8123d
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'int[]' value '[I@39b8123d' to type 'int[]'
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a int[]
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [J@63b58065
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'long[]' value '[J@63b58065' to type 'long[]'
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a long[]
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [S@21009a07
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'short[]' value '[S@21009a07' to type 'short[]'
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a short[]
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [Ljava.math.BigDecimal;@2e80527e
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'BigDecimal[]' value '[Ljava.math.BigDecimal;@2e80527e' to type 'BigDecimal[]'
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a BigDecimal[]
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [Ljava.math.BigInteger;@34f012e1
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'BigInteger[]' value '[Ljava.math.BigInteger;@34f012e1' to type 'BigInteger[]'
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a BigInteger[]
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [Ljava.lang.Boolean;@19555bed
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Boolean[]' value '[Ljava.lang.Boolean;@19555bed' to type 'Boolean[]'
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a Boolean[]
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [Ljava.lang.Byte;@5ba24dfa
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Byte[]' value '[Ljava.lang.Byte;@5ba24dfa' to type 'Byte[]'
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a Byte[]
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [Ljava.lang.Character;@647fb3a5
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Character[]' value '[Ljava.lang.Character;@647fb3a5' to type 'Character[]'
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a Character[]
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [Ljava.lang.Double;@1411aa91
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Double[]' value '[Ljava.lang.Double;@1411aa91' to type 'Double[]'
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a Double[]
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [Ljava.lang.Float;@d20389a
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Float[]' value '[Ljava.lang.Float;@d20389a' to type 'Float[]'
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a Float[]
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [Ljava.lang.Integer;@1a9e2bf7
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Integer[]' value '[Ljava.lang.Integer;@1a9e2bf7' to type 'Integer[]'
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a Integer[]
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [Ljava.lang.Long;@18d7abb9
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Long[]' value '[Ljava.lang.Long;@18d7abb9' to type 'Long[]'
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a Long[]
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [Ljava.lang.Short;@5fdb1ca3
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Short[]' value '[Ljava.lang.Short;@5fdb1ca3' to type 'Short[]'
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a Short[]
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [Ljava.lang.String;@ea0b57f
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'String[]' value '[Ljava.lang.String;@ea0b57f' to type 'String[]'
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a String[]
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [Ljava.lang.Class;@58ebac59
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Class[]' value '[Ljava.lang.Class;@58ebac59' to type 'Class[]'
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a Class[]
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [Ljava.util.Date;@4901b24a
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Date[]' value '[Ljava.util.Date;@4901b24a' to type 'Date[]'
2018-04-12 14:28:26,419 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a Date[]
2018-04-12 14:28:26,435 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [Ljava.util.Calendar;@50740267
2018-04-12 14:28:26,435 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'Calendar[]' value '[Ljava.util.Calendar;@50740267' to type 'Calendar[]'
2018-04-12 14:28:26,435 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a Calendar[]
2018-04-12 14:28:26,435 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [Ljava.io.File;@385eb19c
2018-04-12 14:28:26,435 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'java.io.File[]' value '[Ljava.io.File;@385eb19c' to type 'java.io.File[]'
2018-04-12 14:28:26,435 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a java.io.File[]
2018-04-12 14:28:26,435 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [Ljava.sql.Date;@4534ba55
2018-04-12 14:28:26,435 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'java.sql.Date[]' value '[Ljava.sql.Date;@4534ba55' to type 'java.sql.Date[]'
2018-04-12 14:28:26,435 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a java.sql.Date[]
2018-04-12 14:28:26,435 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [Ljava.sql.Time;@35031755
2018-04-12 14:28:26,435 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'java.sql.Time[]' value '[Ljava.sql.Time;@35031755' to type 'java.sql.Time[]'
2018-04-12 14:28:26,435 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a java.sql.Time[]
2018-04-12 14:28:26,435 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [Ljava.sql.Timestamp;@73395583
2018-04-12 14:28:26,435 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'java.sql.Timestamp[]' value '[Ljava.sql.Timestamp;@73395583' to type 'java.sql.Timestamp[]'
2018-04-12 14:28:26,435 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a java.sql.Timestamp[]
2018-04-12 14:28:26,435 org.apache.commons.beanutils.converters.AbstractConverter.setDefaultValue(AbstractConverter.java:353) DEBUG - Setting default value: [Ljava.net.URL;@310331ed
2018-04-12 14:28:26,435 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'java.net.URL[]' value '[Ljava.net.URL;@310331ed' to type 'java.net.URL[]'
2018-04-12 14:28:26,435 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:162) DEBUG -     No conversion required, value is already a java.net.URL[]
2018-04-12 14:28:26,450 org.apache.commons.beanutils.ConvertUtilsBean.convert(ConvertUtilsBean.java:481) DEBUG - Convert string '/user/login' to class 'java.lang.String'
2018-04-12 14:28:26,450 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'String' value '/user/login' to type 'String'
2018-04-12 14:28:26,450 org.apache.commons.beanutils.ConvertUtilsBean.convert(ConvertUtilsBean.java:481) DEBUG - Convert string '/user/login' to class 'java.lang.String'
2018-04-12 14:28:26,450 org.apache.commons.beanutils.converters.AbstractConverter.convert(AbstractConverter.java:140) DEBUG - Converting 'String' value '/user/login' to type 'String'
2018-04-12 14:28:26,450 org.apache.shiro.realm.AuthorizingRealm.getAuthorizationCacheLazy(AuthorizingRealm.java:234) DEBUG - No authorizationCache instance set.  Checking for a cacheManager...
2018-04-12 14:28:26,450 org.apache.shiro.realm.AuthorizingRealm.getAuthorizationCacheLazy(AuthorizingRealm.java:248) DEBUG - No cache or cacheManager properties have been set.  Authorization cache cannot be obtained.
2018-04-12 14:28:26,450 org.apache.shiro.config.IniFactorySupport.createInstance(IniFactorySupport.java:122) DEBUG - Creating instance from Ini [sections=main,urls]
2018-04-12 14:28:26,470 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.createChain(DefaultFilterChainManager.java:127) DEBUG - Creating chain [/rs/*] from String definition [anon]
2018-04-12 14:28:26,470 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.applyChainConfig(DefaultFilterChainManager.java:278) DEBUG - Attempting to apply path [/rs/*] to filter [anon] with config [null]
2018-04-12 14:28:26,470 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.createChain(DefaultFilterChainManager.java:127) DEBUG - Creating chain [/user/logout] from String definition [anon]
2018-04-12 14:28:26,470 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.applyChainConfig(DefaultFilterChainManager.java:278) DEBUG - Attempting to apply path [/user/logout] to filter [anon] with config [null]
2018-04-12 14:28:26,470 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.createChain(DefaultFilterChainManager.java:127) DEBUG - Creating chain [/user/error] from String definition [anon]
2018-04-12 14:28:26,470 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.applyChainConfig(DefaultFilterChainManager.java:278) DEBUG - Attempting to apply path [/user/error] to filter [anon] with config [null]
2018-04-12 14:28:26,470 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.createChain(DefaultFilterChainManager.java:127) DEBUG - Creating chain [/user/login] from String definition [anon]
2018-04-12 14:28:26,470 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.applyChainConfig(DefaultFilterChainManager.java:278) DEBUG - Attempting to apply path [/user/login] to filter [anon] with config [null]
2018-04-12 14:28:26,470 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.createChain(DefaultFilterChainManager.java:127) DEBUG - Creating chain [/user/profile/active/mail] from String definition [anon]
2018-04-12 14:28:26,470 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.applyChainConfig(DefaultFilterChainManager.java:278) DEBUG - Attempting to apply path [/user/profile/active/mail] to filter [anon] with config [null]
2018-04-12 14:28:26,470 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]
2018-04-12 14:28:26,470 org.apache.shiro.web.env.EnvironmentLoader.initEnvironment(EnvironmentLoader.java:141) INFO  - Shiro environment initialized in 470 ms.
2018-04-12 14:28:26,501 org.nutz.mvc.NutFilter._init(NutFilter.java:85) INFO  - NutFilter[nutz] starting ...
2018-04-12 14:28:26,556 org.nutz.resource.Scans.printLocations(Scans.java:521) DEBUG - Locations count=5 time use 39ms
2018-04-12 14:28:26,706 org.nutz.resource.Scans.printLocations(Scans.java:521) DEBUG - Locations count=29 time use 149ms
2018-04-12 14:28:26,814 org.nutz.castor.Castors.reload(Castors.java:115) DEBUG - Using 95 castor for Castors
2018-04-12 14:28:26,852 org.nutz.mvc.config.AbstractNutConfig.createLoading(AbstractNutConfig.java:59) DEBUG - Loading by class org.nutz.mvc.impl.NutLoading
2018-04-12 14:28:26,854 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:55) INFO  - Nutz Version : 1.r.62 
2018-04-12 14:28:26,854 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:56) INFO  - Nutz.Mvc[nutz] is initializing ...
2018-04-12 14:28:26,854 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:60) DEBUG - Web Container Information:
2018-04-12 14:28:26,854 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:61) DEBUG -  - Default Charset : UTF-8
2018-04-12 14:28:26,854 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:62) DEBUG -  - Current . path  : E:\nutztomcat\tomcat\apache-tomcat-7.0.73\bin\.
2018-04-12 14:28:26,854 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:63) DEBUG -  - Java Version    : 1.6.0_13
2018-04-12 14:28:26,854 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:64) DEBUG -  - File separator  : \
2018-04-12 14:28:26,854 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:65) DEBUG -  - Timezone        : Asia/Shanghai
2018-04-12 14:28:26,854 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:66) DEBUG -  - OS              : Windows Vista amd64
2018-04-12 14:28:26,854 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:67) DEBUG -  - ServerInfo      : Apache Tomcat/7.0.73
2018-04-12 14:28:26,854 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:68) DEBUG -  - Servlet API     : 3.0
2018-04-12 14:28:26,854 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:73) DEBUG -  - ContextPath     : /nutzbook
2018-04-12 14:28:26,854 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:74) DEBUG -  - context.tempdir : E:\nutztomcat\tomcat\apache-tomcat-7.0.73\work\Catalina\localhost\nutzbook
2018-04-12 14:28:26,854 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:75) DEBUG -  - MainModule      : net.wendal.nutzbook.MainModule
2018-04-12 14:28:26,854 org.nutz.mvc.impl.NutLoading.createContext(NutLoading.java:235) DEBUG - >> app.root = E:/nutztomcat/tomcat/apache-tomcat-7.0.73/webapps/nutzbook
2018-04-12 14:28:26,854 org.nutz.mvc.impl.NutLoading.createIoc(NutLoading.java:376) DEBUG - @IocBy(type=org.nutz.mvc.ioc.provider.ComboIocProvider, args=["*js", "ioc/", "*anno", "net.wendal.nutzbook", "*tx", "*quartz"],init=[])
2018-04-12 14:28:26,919 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 2 resource by src( ioc/ ) , regex( ^(.+[.])(js|json)$ )
2018-04-12 14:28:26,919 org.nutz.ioc.loader.json.JsonLoader.<init>(JsonLoader.java:49) DEBUG - loading [dao.js]
2018-04-12 14:28:26,919 org.nutz.ioc.loader.json.JsonLoader.<init>(JsonLoader.java:49) DEBUG - loading [mail.js]
2018-04-12 14:28:26,919 org.nutz.ioc.loader.json.JsonLoader.<init>(JsonLoader.java:57) DEBUG - Loaded 5 bean define from path=[ioc/] --> [htmlEmail, dataSource, dao, conf, emailAuthenticator]
2018-04-12 14:28:26,935 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 18 resource by src( net/wendal/nutzbook/ ) , regex( ^.+[.]class$ )
2018-04-12 14:28:26,987 org.nutz.ioc.loader.annotation.AnnotationIocLoader.addClass(AnnotationIocLoader.java:76) DEBUG - Found @IocBean : class net.wendal.nutzbook.module.CaptchaModule
2018-04-12 14:28:26,987 org.nutz.ioc.loader.annotation.AnnotationIocLoader.addClass(AnnotationIocLoader.java:76) DEBUG - Found @IocBean : class net.wendal.nutzbook.module.UserModule
2018-04-12 14:28:27,002 org.nutz.ioc.loader.annotation.AnnotationIocLoader.addClass(AnnotationIocLoader.java:76) DEBUG - Found @IocBean : class net.wendal.nutzbook.module.UserProfileModule
2018-04-12 14:28:27,018 org.nutz.ioc.loader.annotation.AnnotationIocLoader.addClass(AnnotationIocLoader.java:76) DEBUG - Found @IocBean : class net.wendal.nutzbook.quartz.job.CleanNonActiveUserJob
2018-04-12 14:28:27,018 org.nutz.ioc.loader.annotation.AnnotationIocLoader.addClass(AnnotationIocLoader.java:76) DEBUG - Found @IocBean : class net.wendal.nutzbook.service.EmailServiceImpl
2018-04-12 14:28:27,018 org.nutz.ioc.loader.annotation.AnnotationIocLoader.addClass(AnnotationIocLoader.java:76) DEBUG - Found @IocBean : class net.wendal.nutzbook.service.UserService
2018-04-12 14:28:27,018 org.nutz.ioc.loader.annotation.AnnotationIocLoader.<init>(AnnotationIocLoader.java:52) INFO  - Found 6 classes in 1 base-packages!
beans = ["captchaModule", "cleanNonActiveUserJob", "userProfileModule", "userService", "emailService", "userModule"]
2018-04-12 14:28:27,044 org.nutz.ioc.loader.json.JsonLoader.<init>(JsonLoader.java:40) DEBUG - Loaded 5 bean define from reader --
[txREPEATABLE_READ, txREAD_COMMITTED, txNONE, txSERIALIZABLE, txREAD_UNCOMMITTED]
2018-04-12 14:28:27,048 org.nutz.ioc.loader.combo.ComboIocLoader.createIocLoader(ComboIocLoader.java:110) DEBUG - found quartz -- org.nutz.integration.quartz.QuartzIocLoader
2018-04-12 14:28:27,052 org.nutz.ioc.loader.json.JsonLoader.<init>(JsonLoader.java:57) DEBUG - Loaded 0 bean define from path=[] --> []
2018-04-12 14:28:27,057 org.nutz.ioc.impl.NutIoc.<init>(NutIoc.java:98) INFO  - NutIoc init begin ...
2018-04-12 14:28:27,059 org.nutz.ioc.impl.NutIoc.<init>(NutIoc.java:115) INFO  - ... NutIoc init complete
2018-04-12 14:28:27,062 org.nutz.mvc.impl.NutLoading.evalUrlMapping(NutLoading.java:159) INFO  - Build URL mapping by org.nutz.mvc.impl.UrlMappingImpl ...
2018-04-12 14:28:27,065 org.nutz.mvc.impl.NutLoading.createViewMakers(NutLoading.java:366) DEBUG - @Views(DefaultViewMaker.class)
2018-04-12 14:28:27,076 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 1 resource by src( mvc/nutzbook-mvc-chain.js ) , regex( ^(.+[.])(js|json)$ )
2018-04-12 14:28:27,082 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"
   }
}
2018-04-12 14:28:27,083 org.nutz.mvc.impl.NutLoading.createChainMaker(NutLoading.java:263) DEBUG - @ChainBy(org.nutz.mvc.impl.NutActionChainMaker)
2018-04-12 14:28:27,087 org.nutz.mvc.impl.Loadings.scanModules(Loadings.java:154) DEBUG - module class location 'file:/E:/nutztomcat/tomcat/apache-tomcat-7.0.73/webapps/nutzbook/WEB-INF/classes/'
2018-04-12 14:28:27,087 org.nutz.mvc.impl.Loadings.scanModuleInPackage(Loadings.java:184) DEBUG -  > scan 'net.wendal.nutzbook'
2018-04-12 14:28:27,087 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 18 resource by src( net/wendal/nutzbook/ ) , regex( ^.+[.]class$ )
2018-04-12 14:28:27,087 org.nutz.mvc.impl.Loadings.checkModule(Loadings.java:199) DEBUG -    >> add 'net.wendal.nutzbook.module.CaptchaModule'
2018-04-12 14:28:27,087 org.nutz.mvc.impl.Loadings.checkModule(Loadings.java:199) DEBUG -    >> add 'net.wendal.nutzbook.module.UserModule'
2018-04-12 14:28:27,087 org.nutz.mvc.impl.Loadings.checkModule(Loadings.java:199) DEBUG -    >> add 'net.wendal.nutzbook.module.UserProfileModule'
2018-04-12 14:28:27,171 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/captcha/next'             >> (CaptchaModule.java:23).next          : BufferedImage | @Ok(raw:png) @Fail(jsp:jsp.500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 14:28:27,186 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/get'         >> (UserProfileModule.java:58).get       : UserProfile | @Ok(json:full) @Fail(jsp:jsp.500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 14:28:27,186 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/'            >> (UserProfileModule.java:148).index    : UserProfile | @Ok(jsp:jsp.user.profile) @Fail(jsp:jsp.500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 14:28:27,186 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/update'      >> (UserProfileModule.java:73).update    : void       | @Ok(void ) @Fail(jsp:jsp.500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 14:28:27,202 org.nutz.filepool.NutFilePool.<init>(NutFilePool.java:23) INFO  - Init file-pool by: E:/nutztomcat/tomcat/apache-tomcat-7.0.73/webapps/nutzbook/WEB-INF/tmp/user_avatar [20000]
2018-04-12 14:28:27,202 org.nutz.filepool.NutFilePool.<init>(NutFilePool.java:37) DEBUG - file-pool.home: 'E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\nutzbook\WEB-INF\tmp\user_avatar'
2018-04-12 14:28:27,217 org.nutz.filepool.NutFilePool.<init>(NutFilePool.java:66) INFO  - file-pool.cursor: 0
2018-04-12 14:28:27,217 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/avatar'      >> (UserProfileModule.java:106).uploadAvatar : void       | @Ok(>>:/user/profile) @Fail(jsp:jsp.500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 14:28:27,217 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/avatar'      >> (UserProfileModule.java:136).readAvatar : Object     | @Ok(raw:jpg) @Fail(jsp:jsp.500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 14:28:27,217 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/active/mail' >> (UserProfileModule.java:157).activeMail : Object     | @Ok(json:full) @Fail(jsp:jsp.500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 14:28:27,217 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/active/mail' >> (UserProfileModule.java:184).activeMailCallback : String     | @Ok(raw  ) @Fail(jsp:jsp.500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 14:28:27,287 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/add'                 >> (UserModule.java:81).add              : Object     | @Ok(json:{locked:'password|salt',ignoreNull:true}) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 14:28:27,287 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/count'               >> (UserModule.java:47).count            : int        | @Ok(json:{locked:'password|salt',ignoreNull:true}) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 14:28:27,287 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/delete'              >> (UserModule.java:104).delete          : Object     | @Ok(json:{locked:'password|salt',ignoreNull:true}) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 14:28:27,302 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/query'               >> (UserModule.java:115).query           : Object     | @Ok(json:{locked:'password|salt',ignoreNull:true}) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 14:28:27,303 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/'                    >> (UserModule.java:128).index           : void       | @Ok(jsp:jsp.user.login) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 14:28:27,305 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/update'              >> (UserModule.java:93).update           : Object     | @Ok(json:{locked:'password|salt',ignoreNull:true}) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 14:28:27,306 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/login'               >> (UserModule.java:57).login            : Object     | @Ok(json:{locked:'password|salt',ignoreNull:true}) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 14:28:27,308 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/logout'              >> (UserModule.java:75).logout           : void       | @Ok(>>:/user/) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 14:28:27,309 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/login'               >> (UserModule.java:133).loginPage       : void       | @Ok(jsp:jsp.user.login) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 14:28:27,309 org.nutz.mvc.impl.NutLoading.evalUrlMapping(NutLoading.java:217) INFO  - Found 17 module methods
2018-04-12 14:28:27,310 org.nutz.mvc.impl.NutLoading.evalLocalization(NutLoading.java:303) DEBUG - Localization: org.nutz.mvc.impl.NutMessageLoader('msg/')  dft<zh-CN>
2018-04-12 14:28:27,315 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 1 resource by src( msg/ ) , regex( ^.+[.]properties$ )
2018-04-12 14:28:27,316 org.nutz.mvc.impl.NutMessageLoader.load(NutMessageLoader.java:27) DEBUG - Load Messages in 1 resource : [[File[E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\nutzbook\WEB-INF\classes\msg\zh-CN\user.properties]]]
2018-04-12 14:28:27,318 org.nutz.mvc.impl.NutMessageLoader.load(NutMessageLoader.java:95) DEBUG - Message Loaded, size = 2
2018-04-12 14:28:27,320 org.nutz.mvc.impl.NutLoading.createSessionProvider(NutLoading.java:410) INFO  - SessionBy --> org.nutz.integration.shiro.ShiroSessionProvider@197775c0
2018-04-12 14:28:27,320 org.nutz.mvc.impl.NutLoading.evalSetup(NutLoading.java:271) INFO  - Setup application...
2018-04-12 14:28:27,323 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'dao'<interface org.nutz.dao.Dao>
2018-04-12 14:28:27,325 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
2018-04-12 14:28:27,326 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=dao
2018-04-12 14:28:27,326 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=dao
2018-04-12 14:28:27,331 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:161) DEBUG - Found IocObject(dao) in JsonLoader(paths=[ioc/])
2018-04-12 14:28:27,331 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'dao'<interface org.nutz.dao.Dao>
2018-04-12 14:28:27,346 org.nutz.ioc.aop.impl.DefaultMirrorFactory.getMirror(DefaultMirrorFactory.java:70) DEBUG - Load class org.nutz.dao.impl.NutDao without AOP
2018-04-12 14:28:27,347 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'dao' to [app] 
2018-04-12 14:28:27,350 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'dataSource'<>
2018-04-12 14:28:27,350 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=dataSource
2018-04-12 14:28:27,350 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=dataSource
2018-04-12 14:28:27,353 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:161) DEBUG - Found IocObject(dataSource) in JsonLoader(paths=[ioc/])
2018-04-12 14:28:27,353 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'dataSource'<>
2018-04-12 14:28:27,369 org.nutz.ioc.aop.impl.DefaultMirrorFactory.getMirror(DefaultMirrorFactory.java:70) DEBUG - Load class com.alibaba.druid.pool.DruidDataSource without AOP
2018-04-12 14:28:27,369 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'dataSource' to [app] 
2018-04-12 14:28:27,369 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'conf'<>
2018-04-12 14:28:27,369 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=conf
2018-04-12 14:28:27,369 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=conf
2018-04-12 14:28:27,385 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:161) DEBUG - Found IocObject(conf) in JsonLoader(paths=[ioc/])
2018-04-12 14:28:27,385 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'conf'<>
2018-04-12 14:28:27,385 org.nutz.ioc.aop.impl.DefaultMirrorFactory.getMirror(DefaultMirrorFactory.java:70) DEBUG - Load class org.nutz.ioc.impl.PropertiesProxy without AOP
2018-04-12 14:28:27,385 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'conf' to [app] 
2018-04-12 14:28:27,416 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 3 resource by src( custom/ ) , regex( ^.+[.]properties$ )
2018-04-12 14:28:27,416 org.nutz.ioc.impl.PropertiesProxy.setPaths(PropertiesProxy.java:113) DEBUG - load properties from File[E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\nutzbook\WEB-INF\classes\custom\cron.properties]
2018-04-12 14:28:27,416 org.nutz.ioc.impl.PropertiesProxy.setPaths(PropertiesProxy.java:113) DEBUG - load properties from File[E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\nutzbook\WEB-INF\classes\custom\db.properties]
2018-04-12 14:28:27,416 org.nutz.ioc.impl.PropertiesProxy.setPaths(PropertiesProxy.java:113) DEBUG - load properties from File[E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\nutzbook\WEB-INF\classes\custom\mail.properties]
2018-04-12 14:28:27,691 com.alibaba.druid.pool.DruidDataSource.init(DruidDataSource.java:715) INFO  - {dataSource-1} inited
2018-04-12 14:28:27,691 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'dataSource'<>
2018-04-12 14:28:27,885 org.nutz.dao.jdbc.Jdbcs.<clinit>(Jdbcs.java:90) DEBUG - Jdbcs init complete
2018-04-12 14:28:27,885 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
2018-04-12 14:28:28,128 org.nutz.dao.impl.DaoSupport.setDataSource(DaoSupport.java:188) DEBUG - select expert : org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert
2018-04-12 14:28:28,128 org.nutz.dao.impl.DaoSupport$1.invoke(DaoSupport.java:199) DEBUG - JDBC Driver --> mysql-connector-java-5.1.37 ( Revision: 09940f05b4c98150f352e787a2549f11a2e9da93 )
2018-04-12 14:28:28,128 org.nutz.dao.impl.DaoSupport$1.invoke(DaoSupport.java:200) DEBUG - JDBC Name   --> MySQL Connector Java
2018-04-12 14:28:28,128 org.nutz.dao.impl.DaoSupport$1.invoke(DaoSupport.java:202) DEBUG - JDBC URL    --> jdbc:mysql://127.0.0.1:3306/nutzbook
2018-04-12 14:28:28,241 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:206) DEBUG - Mysql : character_set_client=utf8
2018-04-12 14:28:28,241 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:206) DEBUG - Mysql : character_set_connection=utf8
2018-04-12 14:28:28,241 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:206) DEBUG - Mysql : character_set_database=utf8
2018-04-12 14:28:28,241 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:206) DEBUG - Mysql : character_set_filesystem=binary
2018-04-12 14:28:28,241 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:206) DEBUG - Mysql : character_set_results=
2018-04-12 14:28:28,241 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:206) DEBUG - Mysql : character_set_server=utf8
2018-04-12 14:28:28,241 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:206) DEBUG - Mysql : character_set_system=utf8
2018-04-12 14:28:28,241 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:206) DEBUG - Mysql : character_sets_dir=D:\mysql\share\charsets\
2018-04-12 14:28:28,241 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:213) DEBUG - Mysql : binlog_format=STATEMENT
2018-04-12 14:28:28,241 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:220) DEBUG - Mysql : database=nutzbook
2018-04-12 14:28:28,241 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:226) DEBUG - Mysql : user=root@localhost
2018-04-12 14:28:28,290 org.nutz.dao.impl.DaoSupport.setDataSource(DaoSupport.java:221) DEBUG - Database info --> MYSQL:[MySQL - 5.5.56]
2018-04-12 14:28:28,387 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 18 resource by src( net/wendal/nutzbook/ ) , regex( ^.+[.]class$ )
2018-04-12 14:28:28,387 org.nutz.dao.impl.sql.run.NutDaoExecutor.printSQL(NutDaoExecutor.java:388) DEBUG - SELECT COUNT(*) FROM t_user 
2018-04-12 14:28:28,403 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'nutQuartzCronJobFactory'<class org.nutz.integration.quartz.NutQuartzCronJobFactory>
2018-04-12 14:28:28,403 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=nutQuartzCronJobFactory
2018-04-12 14:28:28,403 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=nutQuartzCronJobFactory
2018-04-12 14:28:28,403 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:161) DEBUG - Found IocObject(nutQuartzCronJobFactory) in QuartzIocLoader@81335012
2018-04-12 14:28:28,403 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'nutQuartzCronJobFactory'<class org.nutz.integration.quartz.NutQuartzCronJobFactory>
2018-04-12 14:28:28,403 org.nutz.ioc.aop.impl.DefaultMirrorFactory.getMirror(DefaultMirrorFactory.java:70) DEBUG - Load class org.nutz.integration.quartz.NutQuartzCronJobFactory without AOP
2018-04-12 14:28:28,403 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'nutQuartzCronJobFactory' to [app] 
2018-04-12 14:28:28,403 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'scheduler'<>
2018-04-12 14:28:28,403 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=scheduler
2018-04-12 14:28:28,403 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=scheduler
2018-04-12 14:28:28,403 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:161) DEBUG - Found IocObject(scheduler) in QuartzIocLoader@81335012
2018-04-12 14:28:28,403 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'scheduler'<>
2018-04-12 14:28:28,403 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'scheduler' to [app] 
2018-04-12 14:28:28,449 org.quartz.impl.StdSchedulerFactory.instantiate(StdSchedulerFactory.java:1172) INFO  - Using default implementation for ThreadExecutor
2018-04-12 14:28:28,469 org.quartz.core.SchedulerSignalerImpl.<init>(SchedulerSignalerImpl.java:61) INFO  - Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
2018-04-12 14:28:28,469 org.quartz.core.QuartzScheduler.<init>(QuartzScheduler.java:240) INFO  - Quartz Scheduler v.2.2.3 created.
2018-04-12 14:28:28,470 org.quartz.simpl.RAMJobStore.initialize(RAMJobStore.java:155) INFO  - RAMJobStore initialized.
2018-04-12 14:28:28,470 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.

2018-04-12 14:28:28,470 org.quartz.impl.StdSchedulerFactory.instantiate(StdSchedulerFactory.java:1327) INFO  - Quartz scheduler 'NutzbookScheduler' initialized from default resource file in Quartz package: 'quartz.properties'
2018-04-12 14:28:28,470 org.quartz.impl.StdSchedulerFactory.instantiate(StdSchedulerFactory.java:1331) INFO  - Quartz scheduler version: 2.2.3
2018-04-12 14:28:28,470 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'jobFactory'<>
2018-04-12 14:28:28,470 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=jobFactory
2018-04-12 14:28:28,470 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=jobFactory
2018-04-12 14:28:28,470 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:161) DEBUG - Found IocObject(jobFactory) in QuartzIocLoader@81335012
2018-04-12 14:28:28,470 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'jobFactory'<>
2018-04-12 14:28:28,470 org.nutz.ioc.aop.impl.DefaultMirrorFactory.getMirror(DefaultMirrorFactory.java:70) DEBUG - Load class org.nutz.integration.quartz.NutQuartzJobFactory without AOP
2018-04-12 14:28:28,470 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'jobFactory' to [app] 
2018-04-12 14:28:28,501 org.quartz.core.QuartzScheduler.setJobFactory(QuartzScheduler.java:2311) INFO  - JobFactory set to: org.nutz.integration.quartz.NutQuartzJobFactory@f9f2a19
2018-04-12 14:28:28,501 org.quartz.core.QuartzScheduler.start(QuartzScheduler.java:575) INFO  - Scheduler NutzbookScheduler_$_NON_CLUSTERED started.
2018-04-12 14:28:28,501 org.quartz.core.QuartzSchedulerThread.run(QuartzSchedulerThread.java:276) DEBUG - batch acquisition of 0 triggers
2018-04-12 14:28:28,501 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'conf'<>
2018-04-12 14:28:28,501 org.nutz.integration.quartz.NutQuartzCronJobFactory.init(NutQuartzCronJobFactory.java:35) DEBUG - job define name=net.wendal.nutzbook.quartz.job.CleanNonActiveUserJob cron=0 0/2 * * * ?
2018-04-12 14:28:28,517 org.nutz.integration.quartz.NutQuartzCronJobFactory.init(NutQuartzCronJobFactory.java:28) DEBUG - found cron job packages = net.wendal.nutzbook.quartz.job
2018-04-12 14:28:28,517 org.quartz.core.QuartzSchedulerThread.run(QuartzSchedulerThread.java:276) DEBUG - batch acquisition of 0 triggers
2018-04-12 14:28:28,517 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 1 resource by src( net/wendal/nutzbook/quartz/job/ ) , regex( ^.+[.]class$ )
2018-04-12 14:28:28,517 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:141) INFO  - Nutz.Mvc[nutz] is up in 1663ms
2018-04-12 14:28:28,517 org.nutz.mvc.NutFilter._init(NutFilter.java:117) INFO  - exclusionsPrefix  = ^(/rs/|/druid/)
2018-4-12 14:28:28 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deployment of web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\nutzbook has finished in 3,751 ms
2018-4-12 14:28:28 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deploying web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\ROOT
2018-4-12 14:28:28 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deployment of web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\ROOT has finished in 37 ms
2018-4-12 14:28:28 org.apache.coyote.AbstractProtocol start
信息: Starting ProtocolHandler ["http-apr-8080"]
2018-4-12 14:28:28 org.apache.coyote.AbstractProtocol start
信息: Starting ProtocolHandler ["ajp-apr-8009"]
2018-4-12 14:28:28 org.apache.catalina.startup.Catalina start
信息: Server startup in 4648 ms
2018-04-12 14:28:28,702 org.nutz.mvc.impl.UrlMappingImpl.get(UrlMappingImpl.java:101) DEBUG - Found mapping for [GET] path=/user/login : UserModule.loginPage(UserModule.java:133)
2018-04-12 14:28:28,702 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'userModule'<class net.wendal.nutzbook.module.UserModule>
2018-04-12 14:28:28,702 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=userModule
2018-04-12 14:28:28,702 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:161) DEBUG - Found IocObject(userModule) in AnnotationIocLoader(packages=[net.wendal.nutzbook])
2018-04-12 14:28:28,702 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'userModule'<class net.wendal.nutzbook.module.UserModule>
2018-04-12 14:28:28,702 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'txREAD_COMMITTED'<interface org.nutz.aop.MethodInterceptor>
2018-04-12 14:28:28,702 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=txREAD_COMMITTED
2018-04-12 14:28:28,702 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=txREAD_COMMITTED
2018-04-12 14:28:28,717 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:161) DEBUG - Found IocObject(txREAD_COMMITTED) in TransIocLoader@2108818823
2018-04-12 14:28:28,717 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'txREAD_COMMITTED'<interface org.nutz.aop.MethodInterceptor>
2018-04-12 14:28:28,717 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'txREAD_COMMITTED' to [app] 
2018-04-12 14:28:28,717 org.nutz.aop.asm.AsmClassAgent.<clinit>(AsmClassAgent.java:29) DEBUG - AsmClassAgent will define class in Version 50
2018-04-12 14:28:28,733 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'userModule' to [app] 
2018-04-12 14:28:28,737 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'userService'<class net.wendal.nutzbook.service.UserService>
2018-04-12 14:28:28,737 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=userService
2018-04-12 14:28:28,737 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:161) DEBUG - Found IocObject(userService) in AnnotationIocLoader(packages=[net.wendal.nutzbook])
2018-04-12 14:28:28,737 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'userService'<class net.wendal.nutzbook.service.UserService>
2018-04-12 14:28:28,737 org.nutz.ioc.aop.impl.DefaultMirrorFactory.getMirror(DefaultMirrorFactory.java:70) DEBUG - Load class net.wendal.nutzbook.service.UserService without AOP
2018-04-12 14:28:28,737 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'userService' to [app] 
2018-04-12 14:28:28,813 org.nutz.service.EntityService.<init>(EntityService.java:41) DEBUG - Get TypeParams for self : net.wendal.nutzbook.bean.User
2018-04-12 14:28:28,813 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'dao'<>
2018-04-12 14:28:28,816 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'dao'<interface org.nutz.dao.Dao>
2018-04-12 14:28:28,816 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'emailService'<interface net.wendal.nutzbook.service.EmailService>
2018-04-12 14:28:28,816 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=emailService
2018-04-12 14:28:28,817 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:161) DEBUG - Found IocObject(emailService) in AnnotationIocLoader(packages=[net.wendal.nutzbook])
2018-04-12 14:28:28,817 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'emailService'<interface net.wendal.nutzbook.service.EmailService>
2018-04-12 14:28:28,817 org.nutz.ioc.aop.impl.DefaultMirrorFactory.getMirror(DefaultMirrorFactory.java:70) DEBUG - Load class net.wendal.nutzbook.service.EmailServiceImpl without AOP
2018-04-12 14:28:28,818 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'emailService' to [app] 
2018-04-12 14:28:28,880 net.wendal.nutzbook.mvc.LogTimeProcessor.process(LogTimeProcessor.java:24) DEBUG - [ GET]URI=/nutzbook/user/login 178ms
2018-04-12 14:28:28,906 org.nutz.mvc.impl.UrlMappingImpl.get(UrlMappingImpl.java:101) DEBUG - Found mapping for [GET] path=/captcha/next : CaptchaModule.next(CaptchaModule.java:23)
2018-04-12 14:28:28,906 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'captchaModule'<class net.wendal.nutzbook.module.CaptchaModule>
2018-04-12 14:28:28,907 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=captchaModule
2018-04-12 14:28:28,907 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:161) DEBUG - Found IocObject(captchaModule) in AnnotationIocLoader(packages=[net.wendal.nutzbook])
2018-04-12 14:28:28,907 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'captchaModule'<class net.wendal.nutzbook.module.CaptchaModule>
2018-04-12 14:28:28,909 org.nutz.ioc.aop.impl.DefaultMirrorFactory.getMirror(DefaultMirrorFactory.java:70) DEBUG - Load class net.wendal.nutzbook.module.CaptchaModule without AOP
2018-04-12 14:28:28,909 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'captchaModule' to [app] 
2018-04-12 14:28:29,279 net.wendal.nutzbook.mvc.LogTimeProcessor.process(LogTimeProcessor.java:24) DEBUG - [ GET]URI=/nutzbook/captcha/next 373ms
2018-04-12 14:28:32,904 org.nutz.mvc.impl.UrlMappingImpl.get(UrlMappingImpl.java:101) DEBUG - Found mapping for [POST] path=/user/login : UserModule.login(UserModule.java:57)
2018-04-12 14:28:32,904 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'userModule'<class net.wendal.nutzbook.module.UserModule>
2018-04-12 14:28:32,904 net.wendal.nutzbook.mvc.LogTimeProcessor.process(LogTimeProcessor.java:24) DEBUG - [POST]URI=/nutzbook/user/login 0ms
2018-04-12 14:28:37,023 org.nutz.mvc.impl.UrlMappingImpl.get(UrlMappingImpl.java:101) DEBUG - Found mapping for [POST] path=/user/login : UserModule.login(UserModule.java:57)
2018-04-12 14:28:37,023 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'userModule'<class net.wendal.nutzbook.module.UserModule>
2018-04-12 14:28:37,066 org.nutz.dao.impl.sql.run.NutDaoExecutor.printSQL(NutDaoExecutor.java:388) DEBUG - SELECT * FROM t_user  WHERE name=?
    |     1 |
    |-------|
    | admin |
  For example:> "SELECT * FROM t_user  WHERE name='admin'"
2018-04-12 14:28:37,099 net.wendal.nutzbook.service.UserService.fetch(UserService.java:33) INFO  - 
页面传入的password：123456
数据库出来的passwd：56f651fff9deda9911619cd4f9b82f62dee3dd82edaaa6ae88855213d3dc5861
查询出来的salt：dee8cf259d1c49669cadb637693f3528
算出来的passwd：5bab4b32c039795e029ff1f16804148596a52df01ef8caedfb7b459599ae1798
是否一致：false
2018-04-12 14:28:37,099 net.wendal.nutzbook.mvc.LogTimeProcessor.process(LogTimeProcessor.java:24) DEBUG - [POST]URI=/nutzbook/user/login 76ms

@wendal

我重新删除表之后按入门手册后面的添加了一些类，然后报错了

2018-4-12 15:36:42 org.apache.catalina.startup.VersionLoggerListener log
信息: Server version:        Apache Tomcat/7.0.73
2018-4-12 15:36:42 org.apache.catalina.startup.VersionLoggerListener log
信息: Server built:          Nov 7 2016 21:27:23 UTC
2018-4-12 15:36:42 org.apache.catalina.startup.VersionLoggerListener log
信息: Server number:         7.0.73.0
2018-4-12 15:36:42 org.apache.catalina.startup.VersionLoggerListener log
信息: OS Name:               Windows Vista
2018-4-12 15:36:42 org.apache.catalina.startup.VersionLoggerListener log
信息: OS Version:            6.1
2018-4-12 15:36:42 org.apache.catalina.startup.VersionLoggerListener log
信息: Architecture:          amd64
2018-4-12 15:36:42 org.apache.catalina.startup.VersionLoggerListener log
信息: Java Home:             D:\myEclipse\Common\binary\com.sun.java.jdk.win32.x86_64_1.6.0.013\jre
2018-4-12 15:36:42 org.apache.catalina.startup.VersionLoggerListener log
信息: JVM Version:           1.6.0_13-b03
2018-4-12 15:36:42 org.apache.catalina.startup.VersionLoggerListener log
信息: JVM Vendor:            Sun Microsystems Inc.
2018-4-12 15:36:42 org.apache.catalina.startup.VersionLoggerListener log
信息: CATALINA_BASE:         E:/nutztomcat/tomcat/apache-tomcat-7.0.73
2018-4-12 15:36:42 org.apache.catalina.startup.VersionLoggerListener log
信息: CATALINA_HOME:         E:/nutztomcat/tomcat/apache-tomcat-7.0.73
2018-4-12 15:36:42 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Dcatalina.home=E:/nutztomcat/tomcat/apache-tomcat-7.0.73
2018-4-12 15:36:42 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Dcatalina.base=E:/nutztomcat/tomcat/apache-tomcat-7.0.73
2018-4-12 15:36:42 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Djava.endorsed.dirs=E:/nutztomcat/tomcat/apache-tomcat-7.0.73/common/endorsed
2018-4-12 15:36:42 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Djava.io.tmpdir=E:/nutztomcat/tomcat/apache-tomcat-7.0.73/temp
2018-4-12 15:36:42 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Djava.library.path=D:/myEclipse/Common/binary/com.sun.java.jdk.win32.x86_64_1.6.0.013/bin;E:/nutztomcat/tomcat/apache-tomcat-7.0.73/bin
2018-4-12 15:36:42 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Dsun.io.useCanonCaches=false
2018-4-12 15:36:42 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Dfile.encoding=UTF-8
2018-4-12 15:36:42 org.apache.catalina.core.AprLifecycleListener lifecycleEvent
信息: Loaded APR based Apache Tomcat Native library 1.2.10 using APR version 1.5.2.
2018-4-12 15:36:42 org.apache.catalina.core.AprLifecycleListener lifecycleEvent
信息: APR capabilities: IPv6 [true], sendfile [true], accept filters [false], random [true].
2018-4-12 15:36:42 org.apache.catalina.core.AprLifecycleListener initializeSSL
信息: OpenSSL successfully initialized (OpenSSL 1.0.2j  26 Sep 2016)
2018-4-12 15:36:42 org.apache.coyote.AbstractProtocol init
信息: Initializing ProtocolHandler ["http-apr-8080"]
2018-4-12 15:36:42 org.apache.coyote.AbstractProtocol init
信息: Initializing ProtocolHandler ["ajp-apr-8009"]
2018-4-12 15:36:42 org.apache.catalina.startup.Catalina load
信息: Initialization processed in 869 ms
2018-4-12 15:36:42 org.apache.catalina.core.StandardService startInternal
信息: Starting service Catalina
2018-4-12 15:36:42 org.apache.catalina.core.StandardEngine startInternal
信息: Starting Servlet Engine: Apache Tomcat/7.0.73
2018-4-12 15:36:42 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deploying web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\docs
2018-4-12 15:36:43 org.apache.tomcat.websocket.server.WsSci onStartup
信息: JSR 356 WebSocket (Java WebSocket 1.1) support is not available when running on Java 6. To suppress this message, run Tomcat on Java 7, remove the WebSocket JARs from $CATALINA_HOME/lib or add the WebSocket JARs to the tomcat.util.scan.DefaultJarScanner.jarsToSkip property in $CATALINA_BASE/conf/catalina.properties. Note that the deprecated Tomcat 7 WebSocket API will be available. 
2018-4-12 15:36:43 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deployment of web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\docs has finished in 381 ms
2018-4-12 15:36:43 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deploying web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\examples
2018-4-12 15:36:43 org.apache.catalina.core.ApplicationContext log
信息: ContextListener: contextInitialized()
2018-4-12 15:36:43 org.apache.catalina.core.ApplicationContext log
信息: SessionListener: contextInitialized()
2018-4-12 15:36:43 org.apache.catalina.core.ApplicationContext log
信息: ContextListener: attributeAdded('org.apache.jasper.compiler.TldLocationsCache', 'org.apache.jasper.compiler.TldLocationsCache@78467991')
2018-4-12 15:36:43 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deployment of web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\examples has finished in 317 ms
2018-4-12 15:36:43 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deploying web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\host-manager
2018-4-12 15:36:43 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deployment of web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\host-manager has finished in 57 ms
2018-4-12 15:36:43 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deploying web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\manager
2018-4-12 15:36:43 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deployment of web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\manager has finished in 51 ms
2018-4-12 15:36:43 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deploying web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\nutzbook
2018-4-12 15:36:44 org.apache.catalina.startup.TaglibUriRule body
信息: TLD skipped. URI: http://java.sun.com/jstl/core is already defined
2018-4-12 15:36:44 org.apache.catalina.startup.TaglibUriRule body
信息: TLD skipped. URI: http://java.sun.com/jstl/fmt is already defined
2018-4-12 15:36:44 org.apache.catalina.startup.TaglibUriRule body
信息: TLD skipped. URI: http://java.sun.com/jstl/sql is already defined
2018-4-12 15:36:44 org.apache.catalina.startup.TaglibUriRule body
信息: TLD skipped. URI: http://java.sun.com/jstl/xml is already defined
2018-4-12 15:36:44 org.apache.catalina.startup.TldConfig execute
信息: 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.
2018-4-12 15:36:44 org.apache.catalina.core.ApplicationContext log
信息: Initializing Shiro environment
2018-04-12 15:36:44,869 org.apache.shiro.web.env.EnvironmentLoader.initEnvironment(EnvironmentLoader.java:128) INFO  - Starting Shiro environment initialization.
2018-04-12 15:36:44,884 org.apache.shiro.web.env.IniWebEnvironment.init(IniWebEnvironment.java:76) DEBUG - Checking any specified config locations.
2018-04-12 15:36:44,885 org.apache.shiro.web.env.IniWebEnvironment.init(IniWebEnvironment.java:81) DEBUG - No INI instance or config locations specified.  Trying default config locations.
2018-04-12 15:36:44,890 org.apache.shiro.io.ResourceUtils.loadFromClassPath(ResourceUtils.java:159) DEBUG - Opening resource from class path [shiro.ini]
2018-04-12 15:36:44,894 org.apache.shiro.config.Ini.load(Ini.java:351) DEBUG - Parsing [main]
2018-04-12 15:36:44,897 org.apache.shiro.config.Ini.load(Ini.java:351) DEBUG - Parsing [urls]
2018-04-12 15:36:44,898 org.apache.shiro.web.env.IniWebEnvironment.getDefaultIni(IniWebEnvironment.java:136) DEBUG - Discovered non-empty INI configuration at location 'classpath:shiro.ini'.  Using for configuration.
2018-04-12 15:36:44,903 org.apache.shiro.config.IniFactorySupport.createInstance(IniFactorySupport.java:122) DEBUG - Creating instance from Ini [sections=main,urls]
2018-04-12 15:36:45,173 org.apache.shiro.realm.AuthorizingRealm.getAuthorizationCacheLazy(AuthorizingRealm.java:234) DEBUG - No authorizationCache instance set.  Checking for a cacheManager...
2018-04-12 15:36:45,174 org.apache.shiro.realm.AuthorizingRealm.getAuthorizationCacheLazy(AuthorizingRealm.java:248) DEBUG - No cache or cacheManager properties have been set.  Authorization cache cannot be obtained.
2018-04-12 15:36:45,174 org.apache.shiro.config.ReflectionBuilder.createNewInstance(ReflectionBuilder.java:296) INFO  - An instance with name 'authc' already exists.  Redefining this object as a new instance of type org.nutz.integration.shiro.SimpleAuthenticationFilter
2018-04-12 15:36:45,251 org.apache.shiro.realm.AuthorizingRealm.getAuthorizationCacheLazy(AuthorizingRealm.java:234) DEBUG - No authorizationCache instance set.  Checking for a cacheManager...
2018-04-12 15:36:45,251 org.apache.shiro.realm.AuthorizingRealm.getAuthorizationCacheLazy(AuthorizingRealm.java:248) DEBUG - No cache or cacheManager properties have been set.  Authorization cache cannot be obtained.
2018-04-12 15:36:45,255 org.apache.shiro.config.IniFactorySupport.createInstance(IniFactorySupport.java:122) DEBUG - Creating instance from Ini [sections=main,urls]
2018-04-12 15:36:45,261 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.createChain(DefaultFilterChainManager.java:127) DEBUG - Creating chain [/rs/*] from String definition [anon]
2018-04-12 15:36:45,262 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.applyChainConfig(DefaultFilterChainManager.java:278) DEBUG - Attempting to apply path [/rs/*] to filter [anon] with config [null]
2018-04-12 15:36:45,265 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.createChain(DefaultFilterChainManager.java:127) DEBUG - Creating chain [/user/logout] from String definition [anon]
2018-04-12 15:36:45,266 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.applyChainConfig(DefaultFilterChainManager.java:278) DEBUG - Attempting to apply path [/user/logout] to filter [anon] with config [null]
2018-04-12 15:36:45,266 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.createChain(DefaultFilterChainManager.java:127) DEBUG - Creating chain [/user/error] from String definition [anon]
2018-04-12 15:36:45,266 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.applyChainConfig(DefaultFilterChainManager.java:278) DEBUG - Attempting to apply path [/user/error] to filter [anon] with config [null]
2018-04-12 15:36:45,267 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.createChain(DefaultFilterChainManager.java:127) DEBUG - Creating chain [/user/login] from String definition [anon]
2018-04-12 15:36:45,267 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.applyChainConfig(DefaultFilterChainManager.java:278) DEBUG - Attempting to apply path [/user/login] to filter [anon] with config [null]
2018-04-12 15:36:45,267 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.createChain(DefaultFilterChainManager.java:127) DEBUG - Creating chain [/user/profile/active/mail] from String definition [anon]
2018-04-12 15:36:45,267 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.applyChainConfig(DefaultFilterChainManager.java:278) DEBUG - Attempting to apply path [/user/profile/active/mail] to filter [anon] with config [null]
2018-04-12 15:36:45,268 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]
2018-04-12 15:36:45,268 org.apache.shiro.web.env.EnvironmentLoader.initEnvironment(EnvironmentLoader.java:141) INFO  - Shiro environment initialized in 396 ms.
2018-04-12 15:36:45,314 org.nutz.mvc.NutFilter._init(NutFilter.java:85) INFO  - NutFilter[nutz] starting ...
2018-04-12 15:36:45,343 org.nutz.resource.Scans.printLocations(Scans.java:521) DEBUG - Locations count=5 time use 16ms
2018-04-12 15:36:45,552 org.nutz.resource.Scans.printLocations(Scans.java:521) DEBUG - Locations count=29 time use 208ms
2018-04-12 15:36:45,638 org.nutz.castor.Castors.reload(Castors.java:115) DEBUG - Using 95 castor for Castors
2018-04-12 15:36:45,673 org.nutz.mvc.config.AbstractNutConfig.createLoading(AbstractNutConfig.java:59) DEBUG - Loading by class org.nutz.mvc.impl.NutLoading
2018-04-12 15:36:45,676 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:55) INFO  - Nutz Version : 1.r.62 
2018-04-12 15:36:45,676 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:56) INFO  - Nutz.Mvc[nutz] is initializing ...
2018-04-12 15:36:45,676 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:60) DEBUG - Web Container Information:
2018-04-12 15:36:45,677 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:61) DEBUG -  - Default Charset : UTF-8
2018-04-12 15:36:45,677 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:62) DEBUG -  - Current . path  : E:\nutztomcat\tomcat\apache-tomcat-7.0.73\bin\.
2018-04-12 15:36:45,678 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:63) DEBUG -  - Java Version    : 1.6.0_13
2018-04-12 15:36:45,678 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:64) DEBUG -  - File separator  : \
2018-04-12 15:36:45,678 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:65) DEBUG -  - Timezone        : Asia/Shanghai
2018-04-12 15:36:45,678 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:66) DEBUG -  - OS              : Windows Vista amd64
2018-04-12 15:36:45,678 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:67) DEBUG -  - ServerInfo      : Apache Tomcat/7.0.73
2018-04-12 15:36:45,678 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:68) DEBUG -  - Servlet API     : 3.0
2018-04-12 15:36:45,679 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:73) DEBUG -  - ContextPath     : /nutzbook
2018-04-12 15:36:45,679 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:74) DEBUG -  - context.tempdir : E:\nutztomcat\tomcat\apache-tomcat-7.0.73\work\Catalina\localhost\nutzbook
2018-04-12 15:36:45,679 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:75) DEBUG -  - MainModule      : net.wendal.nutzbook.MainModule
2018-04-12 15:36:45,679 org.nutz.mvc.impl.NutLoading.createContext(NutLoading.java:235) DEBUG - >> app.root = E:/nutztomcat/tomcat/apache-tomcat-7.0.73/webapps/nutzbook
2018-04-12 15:36:45,682 org.nutz.mvc.impl.NutLoading.createIoc(NutLoading.java:376) DEBUG - @IocBy(type=org.nutz.mvc.ioc.provider.ComboIocProvider, args=["*js", "ioc/", "*anno", "net.wendal.nutzbook", "*tx", "*quartz"],init=[])
2018-04-12 15:36:45,742 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 2 resource by src( ioc/ ) , regex( ^(.+[.])(js|json)$ )
2018-04-12 15:36:45,742 org.nutz.ioc.loader.json.JsonLoader.<init>(JsonLoader.java:49) DEBUG - loading [dao.js]
2018-04-12 15:36:45,748 org.nutz.ioc.loader.json.JsonLoader.<init>(JsonLoader.java:49) DEBUG - loading [mail.js]
2018-04-12 15:36:45,748 org.nutz.ioc.loader.json.JsonLoader.<init>(JsonLoader.java:57) DEBUG - Loaded 5 bean define from path=[ioc/] --> [htmlEmail, dataSource, dao, conf, emailAuthenticator]
2018-04-12 15:36:45,779 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 21 resource by src( net/wendal/nutzbook/ ) , regex( ^.+[.]class$ )
2018-04-12 15:36:45,817 org.nutz.ioc.loader.annotation.AnnotationIocLoader.addClass(AnnotationIocLoader.java:76) DEBUG - Found @IocBean : class net.wendal.nutzbook.module.AuthorityModule
2018-04-12 15:36:45,834 org.nutz.ioc.loader.annotation.AnnotationIocLoader.addClass(AnnotationIocLoader.java:76) DEBUG - Found @IocBean : class net.wendal.nutzbook.module.CaptchaModule
2018-04-12 15:36:45,837 org.nutz.ioc.loader.annotation.AnnotationIocLoader.addClass(AnnotationIocLoader.java:76) DEBUG - Found @IocBean : class net.wendal.nutzbook.module.UserModule
2018-04-12 15:36:45,846 org.nutz.ioc.loader.annotation.AnnotationIocLoader.addClass(AnnotationIocLoader.java:76) DEBUG - Found @IocBean : class net.wendal.nutzbook.module.UserProfileModule
2018-04-12 15:36:45,850 org.nutz.ioc.loader.annotation.AnnotationIocLoader.addClass(AnnotationIocLoader.java:76) DEBUG - Found @IocBean : class net.wendal.nutzbook.quartz.job.CleanNonActiveUserJob
2018-04-12 15:36:45,852 org.nutz.ioc.loader.annotation.AnnotationIocLoader.addClass(AnnotationIocLoader.java:76) DEBUG - Found @IocBean : class net.wendal.nutzbook.service.EmailServiceImpl
2018-04-12 15:36:45,853 org.nutz.ioc.loader.annotation.AnnotationIocLoader.addClass(AnnotationIocLoader.java:76) DEBUG - Found @IocBean : class net.wendal.nutzbook.service.UserService
2018-04-12 15:36:45,857 org.nutz.ioc.loader.annotation.AnnotationIocLoader.<init>(AnnotationIocLoader.java:52) INFO  - Found 7 classes in 1 base-packages!
beans = ["captchaModule", "cleanNonActiveUserJob", "userProfileModule", "userService", "authorityModule", "emailService", "userModule"]
2018-04-12 15:36:45,863 org.nutz.ioc.loader.json.JsonLoader.<init>(JsonLoader.java:40) DEBUG - Loaded 5 bean define from reader --
[txREPEATABLE_READ, txREAD_COMMITTED, txNONE, txSERIALIZABLE, txREAD_UNCOMMITTED]
2018-04-12 15:36:45,866 org.nutz.ioc.loader.combo.ComboIocLoader.createIocLoader(ComboIocLoader.java:110) DEBUG - found quartz -- org.nutz.integration.quartz.QuartzIocLoader
2018-04-12 15:36:45,869 org.nutz.ioc.loader.json.JsonLoader.<init>(JsonLoader.java:57) DEBUG - Loaded 0 bean define from path=[] --> []
2018-04-12 15:36:45,873 org.nutz.ioc.impl.NutIoc.<init>(NutIoc.java:98) INFO  - NutIoc init begin ...
2018-04-12 15:36:45,876 org.nutz.ioc.impl.NutIoc.<init>(NutIoc.java:115) INFO  - ... NutIoc init complete
2018-04-12 15:36:45,879 org.nutz.mvc.impl.NutLoading.evalUrlMapping(NutLoading.java:159) INFO  - Build URL mapping by org.nutz.mvc.impl.UrlMappingImpl ...
2018-04-12 15:36:45,882 org.nutz.mvc.impl.NutLoading.createViewMakers(NutLoading.java:366) DEBUG - @Views(DefaultViewMaker.class)
2018-04-12 15:36:45,892 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 1 resource by src( mvc/nutzbook-mvc-chain.js ) , regex( ^(.+[.])(js|json)$ )
2018-04-12 15:36:45,899 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"
   }
}
2018-04-12 15:36:45,899 org.nutz.mvc.impl.NutLoading.createChainMaker(NutLoading.java:263) DEBUG - @ChainBy(org.nutz.mvc.impl.NutActionChainMaker)
2018-04-12 15:36:45,905 org.nutz.mvc.impl.Loadings.scanModules(Loadings.java:154) DEBUG - module class location 'file:/E:/nutztomcat/tomcat/apache-tomcat-7.0.73/webapps/nutzbook/WEB-INF/classes/'
2018-04-12 15:36:45,905 org.nutz.mvc.impl.Loadings.scanModuleInPackage(Loadings.java:184) DEBUG -  > scan 'net.wendal.nutzbook'
2018-04-12 15:36:45,913 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 21 resource by src( net/wendal/nutzbook/ ) , regex( ^.+[.]class$ )
2018-04-12 15:36:45,917 org.nutz.mvc.impl.Loadings.checkModule(Loadings.java:199) DEBUG -    >> add 'net.wendal.nutzbook.module.AuthorityModule'
2018-04-12 15:36:45,917 org.nutz.mvc.impl.Loadings.checkModule(Loadings.java:199) DEBUG -    >> add 'net.wendal.nutzbook.module.CaptchaModule'
2018-04-12 15:36:45,918 org.nutz.mvc.impl.Loadings.checkModule(Loadings.java:199) DEBUG -    >> add 'net.wendal.nutzbook.module.UserModule'
2018-04-12 15:36:45,918 org.nutz.mvc.impl.Loadings.checkModule(Loadings.java:199) DEBUG -    >> add 'net.wendal.nutzbook.module.UserProfileModule'
2018-04-12 15:36:46,008 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/get'         >> (UserProfileModule.java:58).get       : UserProfile | @Ok(json:full) @Fail(jsp:jsp.500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 15:36:46,017 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/'            >> (UserProfileModule.java:148).index    : UserProfile | @Ok(jsp:jsp.user.profile) @Fail(jsp:jsp.500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 15:36:46,029 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/update'      >> (UserProfileModule.java:73).update    : void       | @Ok(void ) @Fail(jsp:jsp.500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 15:36:46,044 org.nutz.filepool.NutFilePool.<init>(NutFilePool.java:23) INFO  - Init file-pool by: E:/nutztomcat/tomcat/apache-tomcat-7.0.73/webapps/nutzbook/WEB-INF/tmp/user_avatar [20000]
2018-04-12 15:36:46,046 org.nutz.filepool.NutFilePool.<init>(NutFilePool.java:37) DEBUG - file-pool.home: 'E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\nutzbook\WEB-INF\tmp\user_avatar'
2018-04-12 15:36:46,048 org.nutz.filepool.NutFilePool.<init>(NutFilePool.java:66) INFO  - file-pool.cursor: 0
2018-04-12 15:36:46,055 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/avatar'      >> (UserProfileModule.java:106).uploadAvatar : void       | @Ok(>>:/user/profile) @Fail(jsp:jsp.500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 15:36:46,058 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/avatar'      >> (UserProfileModule.java:136).readAvatar : Object     | @Ok(raw:jpg) @Fail(jsp:jsp.500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 15:36:46,059 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/active/mail' >> (UserProfileModule.java:157).activeMail : Object     | @Ok(json:full) @Fail(jsp:jsp.500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 15:36:46,061 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/active/mail' >> (UserProfileModule.java:184).activeMailCallback : String     | @Ok(raw  ) @Fail(jsp:jsp.500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 15:36:46,063 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/admin/authority/user/update' >> (AuthorityModule.java:37).updateUser  : void       | @Ok(void ) @Fail(jsp:jsp.500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 15:36:46,123 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/add'                 >> (UserModule.java:82).add              : Object     | @Ok(json:{locked:'password|salt',ignoreNull:true}) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 15:36:46,124 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/count'               >> (UserModule.java:48).count            : int        | @Ok(json:{locked:'password|salt',ignoreNull:true}) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 15:36:46,126 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/delete'              >> (UserModule.java:105).delete          : Object     | @Ok(json:{locked:'password|salt',ignoreNull:true}) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 15:36:46,133 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/query'               >> (UserModule.java:117).query           : Object     | @Ok(json:{locked:'password|salt',ignoreNull:true}) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 15:36:46,134 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/'                    >> (UserModule.java:130).index           : void       | @Ok(jsp:jsp.user.login) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 15:36:46,135 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/update'              >> (UserModule.java:94).update           : Object     | @Ok(json:{locked:'password|salt',ignoreNull:true}) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 15:36:46,136 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/login'               >> (UserModule.java:58).login            : Object     | @Ok(json:{locked:'password|salt',ignoreNull:true}) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 15:36:46,137 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/logout'              >> (UserModule.java:76).logout           : void       | @Ok(>>:/user/) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 15:36:46,138 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/login'               >> (UserModule.java:135).loginPage       : void       | @Ok(jsp:jsp.user.login) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 15:36:46,140 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/captcha/next'             >> (CaptchaModule.java:23).next          : BufferedImage | @Ok(raw:png) @Fail(jsp:jsp.500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 15:36:46,140 org.nutz.mvc.impl.NutLoading.evalUrlMapping(NutLoading.java:217) INFO  - Found 18 module methods
2018-04-12 15:36:46,140 org.nutz.mvc.impl.NutLoading.evalLocalization(NutLoading.java:303) DEBUG - Localization: org.nutz.mvc.impl.NutMessageLoader('msg/')  dft<zh-CN>
2018-04-12 15:36:46,143 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 1 resource by src( msg/ ) , regex( ^.+[.]properties$ )
2018-04-12 15:36:46,143 org.nutz.mvc.impl.NutMessageLoader.load(NutMessageLoader.java:27) DEBUG - Load Messages in 1 resource : [[File[E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\nutzbook\WEB-INF\classes\msg\zh-CN\user.properties]]]
2018-04-12 15:36:46,145 org.nutz.mvc.impl.NutMessageLoader.load(NutMessageLoader.java:95) DEBUG - Message Loaded, size = 2
2018-04-12 15:36:46,148 org.nutz.mvc.impl.NutLoading.createSessionProvider(NutLoading.java:410) INFO  - SessionBy --> org.nutz.integration.shiro.ShiroSessionProvider@28f549de
2018-04-12 15:36:46,148 org.nutz.mvc.impl.NutLoading.evalSetup(NutLoading.java:271) INFO  - Setup application...
2018-04-12 15:36:46,151 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'dao'<interface org.nutz.dao.Dao>
2018-04-12 15:36:46,152 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
2018-04-12 15:36:46,153 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=dao
2018-04-12 15:36:46,153 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=dao
2018-04-12 15:36:46,157 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:161) DEBUG - Found IocObject(dao) in JsonLoader(paths=[ioc/])
2018-04-12 15:36:46,157 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'dao'<interface org.nutz.dao.Dao>
2018-04-12 15:36:46,167 org.nutz.ioc.aop.impl.DefaultMirrorFactory.getMirror(DefaultMirrorFactory.java:70) DEBUG - Load class org.nutz.dao.impl.NutDao without AOP
2018-04-12 15:36:46,168 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'dao' to [app] 
2018-04-12 15:36:46,171 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'dataSource'<>
2018-04-12 15:36:46,171 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=dataSource
2018-04-12 15:36:46,171 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=dataSource
2018-04-12 15:36:46,181 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:161) DEBUG - Found IocObject(dataSource) in JsonLoader(paths=[ioc/])
2018-04-12 15:36:46,181 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'dataSource'<>
2018-04-12 15:36:46,199 org.nutz.ioc.aop.impl.DefaultMirrorFactory.getMirror(DefaultMirrorFactory.java:70) DEBUG - Load class com.alibaba.druid.pool.DruidDataSource without AOP
2018-04-12 15:36:46,199 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'dataSource' to [app] 
2018-04-12 15:36:46,201 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'conf'<>
2018-04-12 15:36:46,201 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=conf
2018-04-12 15:36:46,202 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=conf
2018-04-12 15:36:46,212 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:161) DEBUG - Found IocObject(conf) in JsonLoader(paths=[ioc/])
2018-04-12 15:36:46,212 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'conf'<>
2018-04-12 15:36:46,213 org.nutz.ioc.aop.impl.DefaultMirrorFactory.getMirror(DefaultMirrorFactory.java:70) DEBUG - Load class org.nutz.ioc.impl.PropertiesProxy without AOP
2018-04-12 15:36:46,213 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'conf' to [app] 
2018-04-12 15:36:46,252 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 3 resource by src( custom/ ) , regex( ^.+[.]properties$ )
2018-04-12 15:36:46,253 org.nutz.ioc.impl.PropertiesProxy.setPaths(PropertiesProxy.java:113) DEBUG - load properties from File[E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\nutzbook\WEB-INF\classes\custom\cron.properties]
2018-04-12 15:36:46,253 org.nutz.ioc.impl.PropertiesProxy.setPaths(PropertiesProxy.java:113) DEBUG - load properties from File[E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\nutzbook\WEB-INF\classes\custom\db.properties]
2018-04-12 15:36:46,254 org.nutz.ioc.impl.PropertiesProxy.setPaths(PropertiesProxy.java:113) DEBUG - load properties from File[E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\nutzbook\WEB-INF\classes\custom\mail.properties]
2018-04-12 15:36:46,536 com.alibaba.druid.pool.DruidDataSource.init(DruidDataSource.java:715) INFO  - {dataSource-1} inited
2018-04-12 15:36:46,537 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'dataSource'<>
2018-04-12 15:36:46,717 org.nutz.dao.jdbc.Jdbcs.<clinit>(Jdbcs.java:90) DEBUG - Jdbcs init complete
2018-04-12 15:36:46,717 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
2018-04-12 15:36:46,996 org.nutz.dao.impl.DaoSupport.setDataSource(DaoSupport.java:188) DEBUG - select expert : org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert
2018-04-12 15:36:47,006 org.nutz.dao.impl.DaoSupport$1.invoke(DaoSupport.java:199) DEBUG - JDBC Driver --> mysql-connector-java-5.1.37 ( Revision: 09940f05b4c98150f352e787a2549f11a2e9da93 )
2018-04-12 15:36:47,006 org.nutz.dao.impl.DaoSupport$1.invoke(DaoSupport.java:200) DEBUG - JDBC Name   --> MySQL Connector Java
2018-04-12 15:36:47,007 org.nutz.dao.impl.DaoSupport$1.invoke(DaoSupport.java:202) DEBUG - JDBC URL    --> jdbc:mysql://127.0.0.1:3306/nutzbook
2018-04-12 15:36:47,111 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:206) DEBUG - Mysql : character_set_client=utf8
2018-04-12 15:36:47,111 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:206) DEBUG - Mysql : character_set_connection=utf8
2018-04-12 15:36:47,111 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:206) DEBUG - Mysql : character_set_database=utf8
2018-04-12 15:36:47,112 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:206) DEBUG - Mysql : character_set_filesystem=binary
2018-04-12 15:36:47,112 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:206) DEBUG - Mysql : character_set_results=
2018-04-12 15:36:47,112 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:206) DEBUG - Mysql : character_set_server=utf8
2018-04-12 15:36:47,112 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:206) DEBUG - Mysql : character_set_system=utf8
2018-04-12 15:36:47,112 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:206) DEBUG - Mysql : character_sets_dir=D:\mysql\share\charsets\
2018-04-12 15:36:47,114 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:213) DEBUG - Mysql : binlog_format=STATEMENT
2018-04-12 15:36:47,114 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:220) DEBUG - Mysql : database=nutzbook
2018-04-12 15:36:47,115 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:226) DEBUG - Mysql : user=root@localhost
2018-04-12 15:36:47,153 org.nutz.dao.impl.DaoSupport.setDataSource(DaoSupport.java:221) DEBUG - Database info --> MYSQL:[MySQL - 5.5.56]
2018-04-12 15:36:47,235 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 21 resource by src( net/wendal/nutzbook/ ) , regex( ^.+[.]class$ )
2018-04-12 15:36:47,248 org.nutz.dao.impl.sql.run.NutDaoExecutor.printSQL(NutDaoExecutor.java:388) DEBUG - SELECT COUNT(*) FROM t_user 
2018-04-12 15:36:47,251 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'nutQuartzCronJobFactory'<class org.nutz.integration.quartz.NutQuartzCronJobFactory>
2018-04-12 15:36:47,251 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=nutQuartzCronJobFactory
2018-04-12 15:36:47,251 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=nutQuartzCronJobFactory
2018-04-12 15:36:47,252 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:161) DEBUG - Found IocObject(nutQuartzCronJobFactory) in QuartzIocLoader@1914746658
2018-04-12 15:36:47,252 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'nutQuartzCronJobFactory'<class org.nutz.integration.quartz.NutQuartzCronJobFactory>
2018-04-12 15:36:47,254 org.nutz.ioc.aop.impl.DefaultMirrorFactory.getMirror(DefaultMirrorFactory.java:70) DEBUG - Load class org.nutz.integration.quartz.NutQuartzCronJobFactory without AOP
2018-04-12 15:36:47,254 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'nutQuartzCronJobFactory' to [app] 
2018-04-12 15:36:47,260 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'scheduler'<>
2018-04-12 15:36:47,261 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=scheduler
2018-04-12 15:36:47,261 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=scheduler
2018-04-12 15:36:47,262 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:161) DEBUG - Found IocObject(scheduler) in QuartzIocLoader@1914746658
2018-04-12 15:36:47,262 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'scheduler'<>
2018-04-12 15:36:47,262 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'scheduler' to [app] 
2018-04-12 15:36:47,304 org.quartz.impl.StdSchedulerFactory.instantiate(StdSchedulerFactory.java:1172) INFO  - Using default implementation for ThreadExecutor
2018-04-12 15:36:47,322 org.quartz.core.SchedulerSignalerImpl.<init>(SchedulerSignalerImpl.java:61) INFO  - Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
2018-04-12 15:36:47,323 org.quartz.core.QuartzScheduler.<init>(QuartzScheduler.java:240) INFO  - Quartz Scheduler v.2.2.3 created.
2018-04-12 15:36:47,324 org.quartz.simpl.RAMJobStore.initialize(RAMJobStore.java:155) INFO  - RAMJobStore initialized.
2018-04-12 15:36:47,324 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.

2018-04-12 15:36:47,325 org.quartz.impl.StdSchedulerFactory.instantiate(StdSchedulerFactory.java:1327) INFO  - Quartz scheduler 'NutzbookScheduler' initialized from default resource file in Quartz package: 'quartz.properties'
2018-04-12 15:36:47,325 org.quartz.impl.StdSchedulerFactory.instantiate(StdSchedulerFactory.java:1331) INFO  - Quartz scheduler version: 2.2.3
2018-04-12 15:36:47,325 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'jobFactory'<>
2018-04-12 15:36:47,325 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=jobFactory
2018-04-12 15:36:47,326 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=jobFactory
2018-04-12 15:36:47,327 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:161) DEBUG - Found IocObject(jobFactory) in QuartzIocLoader@1914746658
2018-04-12 15:36:47,327 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'jobFactory'<>
2018-04-12 15:36:47,328 org.nutz.ioc.aop.impl.DefaultMirrorFactory.getMirror(DefaultMirrorFactory.java:70) DEBUG - Load class org.nutz.integration.quartz.NutQuartzJobFactory without AOP
2018-04-12 15:36:47,328 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'jobFactory' to [app] 
2018-04-12 15:36:47,365 org.quartz.core.QuartzScheduler.setJobFactory(QuartzScheduler.java:2311) INFO  - JobFactory set to: org.nutz.integration.quartz.NutQuartzJobFactory@5704a4b6
2018-04-12 15:36:47,365 org.quartz.core.QuartzScheduler.start(QuartzScheduler.java:575) INFO  - Scheduler NutzbookScheduler_$_NON_CLUSTERED started.
2018-04-12 15:36:47,366 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'conf'<>
2018-04-12 15:36:47,366 org.nutz.integration.quartz.NutQuartzCronJobFactory.init(NutQuartzCronJobFactory.java:35) DEBUG - job define name=net.wendal.nutzbook.quartz.job.CleanNonActiveUserJob cron=0 0/2 * * * ?
2018-04-12 15:36:47,381 org.nutz.integration.quartz.NutQuartzCronJobFactory.init(NutQuartzCronJobFactory.java:28) DEBUG - found cron job packages = net.wendal.nutzbook.quartz.job
2018-04-12 15:36:47,382 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 1 resource by src( net/wendal/nutzbook/quartz/job/ ) , regex( ^.+[.]class$ )
2018-04-12 15:36:47,383 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'authorityService'<interface net.wendal.nutzbook.service.AuthorityService>
2018-04-12 15:36:47,383 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=authorityService
2018-04-12 15:36:47,384 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:125) ERROR - Error happend during start serivce!
org.nutz.ioc.IocException: IocBean[authorityService] For object [authorityService] - type:[interface net.wendal.nutzbook.service.AuthorityService]
	at org.nutz.ioc.impl.NutIoc.get(NutIoc.java:218)
	at org.nutz.ioc.impl.NutIoc.get(NutIoc.java:239)
	at org.nutz.ioc.impl.NutIoc.get(NutIoc.java:146)
	at net.wendal.nutzbook.MainSetup.init(MainSetup.java:34)
	at org.nutz.mvc.impl.NutLoading.evalSetup(NutLoading.java:274)
	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:91)
	at org.nutz.mvc.NutFilter.init(NutFilter.java:69)
	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:4958)
	at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5652)
	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:145)
	at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:899)
	at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:875)
	at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:652)
	at org.apache.catalina.startup.HostConfig.deployDirectory(HostConfig.java:1260)
	at org.apache.catalina.startup.HostConfig$DeployDirectory.run(HostConfig.java:2002)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
	at java.util.concurrent.FutureTask.run(FutureTask.java:138)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:619)
Caused by: org.nutz.ioc.ObjectLoadException: Object 'authorityService' without define!
	at org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:166)
	at org.nutz.ioc.impl.NutIoc.get(NutIoc.java:180)
	... 25 more
2018-04-12 15:36:47,386 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:127) ERROR - try to depose ioc
2018-04-12 15:36:47,389 org.nutz.ioc.impl.NutIoc.depose(NutIoc.java:255) INFO  - org.nutz.ioc.impl.NutIoc@1241012870 is closing. startup date [18-04-12 15:36:45.874]
2018-04-12 15:36:47,389 org.nutz.ioc.impl.ScopeContext.clear(ScopeContext.java:108) DEBUG - Depose object 'jobFactory' ...
2018-04-12 15:36:47,389 org.nutz.ioc.impl.ScopeContext.clear(ScopeContext.java:108) DEBUG - Depose object 'scheduler' ...
2018-04-12 15:36:47,390 org.quartz.core.QuartzScheduler.shutdown(QuartzScheduler.java:694) INFO  - Scheduler NutzbookScheduler_$_NON_CLUSTERED shutting down.
2018-04-12 15:36:47,390 org.quartz.core.QuartzScheduler.standby(QuartzScheduler.java:613) INFO  - Scheduler NutzbookScheduler_$_NON_CLUSTERED paused.
2018-04-12 15:36:47,390 org.quartz.simpl.SimpleThreadPool.shutdown(SimpleThreadPool.java:328) DEBUG - Shutting down threadpool...
2018-04-12 15:36:47,391 org.quartz.simpl.SimpleThreadPool.shutdown(SimpleThreadPool.java:395) DEBUG - Shutdown of threadpool complete.
2018-04-12 15:36:47,391 org.quartz.core.QuartzScheduler.shutdown(QuartzScheduler.java:771) INFO  - Scheduler NutzbookScheduler_$_NON_CLUSTERED shutdown complete.
2018-04-12 15:36:47,391 org.nutz.ioc.impl.ScopeContext.clear(ScopeContext.java:108) DEBUG - Depose object 'nutQuartzCronJobFactory' ...
2018-04-12 15:36:47,391 org.nutz.ioc.impl.ScopeContext.clear(ScopeContext.java:108) DEBUG - Depose object 'conf' ...
2018-04-12 15:36:47,391 org.nutz.ioc.impl.ScopeContext.clear(ScopeContext.java:108) DEBUG - Depose object 'dao' ...
2018-04-12 15:36:47,391 org.nutz.ioc.impl.ScopeContext.clear(ScopeContext.java:113) DEBUG - Depose object 'dataSource' ...
2018-04-12 15:36:47,396 com.alibaba.druid.pool.DruidDataSource.close(DruidDataSource.java:1444) INFO  - {dataSource-1} closed
2018-04-12 15:36:47,396 org.nutz.ioc.impl.NutIoc.depose(NutIoc.java:262) INFO  - org.nutz.ioc.impl.NutIoc@1241012870 is deposed. startup date [18-04-12 15:36:45.874]
2018-4-12 15:36:47 org.apache.catalina.core.StandardContext filterStart
严重: Exception starting filter nutz
org.nutz.mvc.LoadingException: org.nutz.ioc.IocException: IocBean[authorityService] For object [authorityService] - type:[interface net.wendal.nutzbook.service.AuthorityService]
	at org.nutz.mvc.LoadingException$FC$9a86caf9ff5d3b587784fcdf555a4a7d.invoke(LoadingException.java)
	at org.nutz.lang.born.AbstractConstructorBorning.call(AbstractConstructorBorning.java:25)
	at org.nutz.lang.born.ConstructorBorning.born(ConstructorBorning.java:19)
	at org.nutz.lang.born.BornContext.doBorn(BornContext.java:60)
	at org.nutz.lang.Mirror.born(Mirror.java:990)
	at org.nutz.lang.Lang.wrapThrow(Lang.java:200)
	at org.nutz.mvc.impl.NutLoading.load(NutLoading.java:135)
	at org.nutz.mvc.ActionHandler.<init>(ActionHandler.java:19)
	at org.nutz.mvc.NutFilter._init(NutFilter.java:91)
	at org.nutz.mvc.NutFilter.init(NutFilter.java:69)
	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:4958)
	at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5652)
	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:145)
	at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:899)
	at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:875)
	at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:652)
	at org.apache.catalina.startup.HostConfig.deployDirectory(HostConfig.java:1260)
	at org.apache.catalina.startup.HostConfig$DeployDirectory.run(HostConfig.java:2002)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
	at java.util.concurrent.FutureTask.run(FutureTask.java:138)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:619)
Caused by: org.nutz.ioc.IocException: IocBean[authorityService] For object [authorityService] - type:[interface net.wendal.nutzbook.service.AuthorityService]
	at org.nutz.ioc.impl.NutIoc.get(NutIoc.java:218)
	at org.nutz.ioc.impl.NutIoc.get(NutIoc.java:239)
	at org.nutz.ioc.impl.NutIoc.get(NutIoc.java:146)
	at net.wendal.nutzbook.MainSetup.init(MainSetup.java:34)
	at org.nutz.mvc.impl.NutLoading.evalSetup(NutLoading.java:274)
	at org.nutz.mvc.impl.NutLoading.load(NutLoading.java:121)
	... 20 more
Caused by: org.nutz.ioc.ObjectLoadException: Object 'authorityService' without define!
	at org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:166)
	at org.nutz.ioc.impl.NutIoc.get(NutIoc.java:180)
	... 25 more
2018-4-12 15:36:47 org.apache.catalina.core.StandardContext startInternal
严重: One or more Filters failed to start. Full details will be found in the appropriate container log file
2018-4-12 15:36:47 org.apache.catalina.core.StandardContext startInternal
严重: Context [/nutzbook] startup failed due to previous errors
2018-4-12 15:36:47 org.apache.catalina.core.ApplicationContext log
信息: Cleaning up Shiro Environment
2018-4-12 15:36:47 org.apache.catalina.loader.WebappClassLoaderBase clearReferencesJdbc
严重: The web application [/nutzbook] registered the JDBC driver [com.alibaba.druid.proxy.DruidDriver] but failed to unregister it when the web application was stopped. To prevent a memory leak, the JDBC Driver has been forcibly unregistered.
2018-4-12 15:36:47 org.apache.catalina.loader.WebappClassLoaderBase clearReferencesJdbc
严重: The web application [/nutzbook] registered the JDBC driver [com.mysql.jdbc.Driver] but failed to unregister it when the web application was stopped. To prevent a memory leak, the JDBC Driver has been forcibly unregistered.
2018-4-12 15:36:47 org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
严重: The web application [/nutzbook] appears to have started a thread named [Abandoned connection cleanup thread] but has failed to stop it. This is very likely to create a memory leak.
2018-4-12 15:36:47 org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
严重: The web application [/nutzbook] appears to have started a thread named [NutzbookScheduler_Worker-1] but has failed to stop it. This is very likely to create a memory leak.
2018-4-12 15:36:47 org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
严重: The web application [/nutzbook] appears to have started a thread named [NutzbookScheduler_Worker-2] but has failed to stop it. This is very likely to create a memory leak.
2018-4-12 15:36:47 org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
严重: The web application [/nutzbook] appears to have started a thread named [NutzbookScheduler_Worker-3] but has failed to stop it. This is very likely to create a memory leak.
2018-4-12 15:36:47 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deployment of web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\nutzbook has finished in 3,948 ms
2018-4-12 15:36:47 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deploying web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\ROOT
2018-4-12 15:36:47 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deployment of web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\ROOT has finished in 57 ms
2018-4-12 15:36:47 org.apache.coyote.AbstractProtocol start
信息: Starting ProtocolHandler ["http-apr-8080"]
2018-4-12 15:36:47 org.apache.coyote.AbstractProtocol start
信息: Starting ProtocolHandler ["ajp-apr-8009"]
2018-4-12 15:36:47 org.apache.catalina.startup.Catalina start
信息: Server startup in 4862 ms
2018-04-12 15:36:47,810 org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:612) DEBUG - WorkerThread is shut down.
2018-04-12 15:36:47,810 org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:612) DEBUG - WorkerThread is shut down.
2018-04-12 15:36:47,812 org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:612) DEBUG - WorkerThread is shut down.

AuthorityService.java

package net.wendal.nutzbook.service;

import net.wendal.nutzbook.bean.Role;
import net.wendal.nutzbook.bean.User;

public interface AuthorityService {

    /**
     * 扫描RequiresPermissions和RequiresRoles注解
     * @param pkg 需要扫描的package
     */
    void initFormPackage(String pkg);

    /**
     * 检查最基础的权限,确保admin用户-admin角色-(用户增删改查-权限增删改查)这一基础权限设置
     * @param admin
     */
    void checkBasicRoles(User admin);

    /**
     * 添加一个权限
     */
    public void addPermission(String permission);

    /**
     * 添加一个角色
     */
    public Role addRole(String role);
}

AuthorityServiceImpl.java

package net.wendal.nutzbook.service;

import java.util.List;

import org.nutz.dao.Chain;
import org.nutz.dao.Cnd;
import org.nutz.dao.Dao;
import org.nutz.dao.entity.Record;
import org.nutz.ioc.loader.annotation.Inject;

import net.wendal.nutzbook.bean.Permission;
import net.wendal.nutzbook.bean.Role;
import net.wendal.nutzbook.bean.User;

public class AuthorityServiceImpl implements AuthorityService{
	
	@Inject
	private Dao dao;
	@Override
	 public void checkBasicRoles(User admin) {
	        // 检查一下admin的权限
	        Role adminRole = dao.fetch(Role.class, "admin");
	        if (adminRole == null) {
	            adminRole = addRole("admin");
	        }
	        // admin账号必须存在与admin组
	        if (0 == dao.count("t_user_role", Cnd.where("u_id", "=", admin.getId()).and("role_id", "=", adminRole.getId()))) {
	            dao.insert("t_user_role", Chain.make("u_id", admin.getId()).add("role_id", adminRole.getId()));
	        }
	        // admin组必须有authority:* 也就是权限管理相关的权限
	        List<Record> res = dao.query("t_role_permission", Cnd.where("role_id", "=", adminRole.getId()));
	        OUT: for (Permission permission : dao.query(Permission.class, Cnd.where("name", "like", "authority:%").or("name", "like", "user:%"), null)) {
	            for (Record re : res) {
	                if (re.getInt("permission_id") == permission.getId())
	                    continue OUT;
	            }
	            dao.insert("t_role_permission", Chain.make("role_id", adminRole.getId()).add("permission_id", permission.getId()));
	        };
	    }
	@Override
	public void initFormPackage(String pkg) {
		
	}
	@Override
	public void addPermission(String permission) {
		
	}
	@Override
	public Role addRole(String role) {
		return null;
	}

}

@wendal

大佬 ，请问这是什么问题
@wendal

2018-4-12 16:05:51 org.apache.catalina.startup.VersionLoggerListener log
信息: Server version:        Apache Tomcat/7.0.73
2018-4-12 16:05:51 org.apache.catalina.startup.VersionLoggerListener log
信息: Server built:          Nov 7 2016 21:27:23 UTC
2018-4-12 16:05:51 org.apache.catalina.startup.VersionLoggerListener log
信息: Server number:         7.0.73.0
2018-4-12 16:05:51 org.apache.catalina.startup.VersionLoggerListener log
信息: OS Name:               Windows Vista
2018-4-12 16:05:51 org.apache.catalina.startup.VersionLoggerListener log
信息: OS Version:            6.1
2018-4-12 16:05:51 org.apache.catalina.startup.VersionLoggerListener log
信息: Architecture:          amd64
2018-4-12 16:05:51 org.apache.catalina.startup.VersionLoggerListener log
信息: Java Home:             D:\myEclipse\Common\binary\com.sun.java.jdk.win32.x86_64_1.6.0.013\jre
2018-4-12 16:05:51 org.apache.catalina.startup.VersionLoggerListener log
信息: JVM Version:           1.6.0_13-b03
2018-4-12 16:05:51 org.apache.catalina.startup.VersionLoggerListener log
信息: JVM Vendor:            Sun Microsystems Inc.
2018-4-12 16:05:51 org.apache.catalina.startup.VersionLoggerListener log
信息: CATALINA_BASE:         E:/nutztomcat/tomcat/apache-tomcat-7.0.73
2018-4-12 16:05:51 org.apache.catalina.startup.VersionLoggerListener log
信息: CATALINA_HOME:         E:/nutztomcat/tomcat/apache-tomcat-7.0.73
2018-4-12 16:05:51 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Dcatalina.home=E:/nutztomcat/tomcat/apache-tomcat-7.0.73
2018-4-12 16:05:51 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Dcatalina.base=E:/nutztomcat/tomcat/apache-tomcat-7.0.73
2018-4-12 16:05:51 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Djava.endorsed.dirs=E:/nutztomcat/tomcat/apache-tomcat-7.0.73/common/endorsed
2018-4-12 16:05:51 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Djava.io.tmpdir=E:/nutztomcat/tomcat/apache-tomcat-7.0.73/temp
2018-4-12 16:05:51 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Djava.library.path=D:/myEclipse/Common/binary/com.sun.java.jdk.win32.x86_64_1.6.0.013/bin;E:/nutztomcat/tomcat/apache-tomcat-7.0.73/bin
2018-4-12 16:05:51 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Dsun.io.useCanonCaches=false
2018-4-12 16:05:51 org.apache.catalina.startup.VersionLoggerListener log
信息: Command line argument: -Dfile.encoding=UTF-8
2018-4-12 16:05:51 org.apache.catalina.core.AprLifecycleListener lifecycleEvent
信息: Loaded APR based Apache Tomcat Native library 1.2.10 using APR version 1.5.2.
2018-4-12 16:05:51 org.apache.catalina.core.AprLifecycleListener lifecycleEvent
信息: APR capabilities: IPv6 [true], sendfile [true], accept filters [false], random [true].
2018-4-12 16:05:52 org.apache.catalina.core.AprLifecycleListener initializeSSL
信息: OpenSSL successfully initialized (OpenSSL 1.0.2j  26 Sep 2016)
2018-4-12 16:05:52 org.apache.coyote.AbstractProtocol init
信息: Initializing ProtocolHandler ["http-apr-8080"]
2018-4-12 16:05:52 org.apache.coyote.AbstractProtocol init
信息: Initializing ProtocolHandler ["ajp-apr-8009"]
2018-4-12 16:05:52 org.apache.catalina.startup.Catalina load
信息: Initialization processed in 983 ms
2018-4-12 16:05:52 org.apache.catalina.core.StandardService startInternal
信息: Starting service Catalina
2018-4-12 16:05:52 org.apache.catalina.core.StandardEngine startInternal
信息: Starting Servlet Engine: Apache Tomcat/7.0.73
2018-4-12 16:05:52 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deploying web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\docs
2018-4-12 16:05:52 org.apache.tomcat.websocket.server.WsSci onStartup
信息: JSR 356 WebSocket (Java WebSocket 1.1) support is not available when running on Java 6. To suppress this message, run Tomcat on Java 7, remove the WebSocket JARs from $CATALINA_HOME/lib or add the WebSocket JARs to the tomcat.util.scan.DefaultJarScanner.jarsToSkip property in $CATALINA_BASE/conf/catalina.properties. Note that the deprecated Tomcat 7 WebSocket API will be available. 
2018-4-12 16:05:52 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deployment of web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\docs has finished in 390 ms
2018-4-12 16:05:52 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deploying web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\examples
2018-4-12 16:05:52 org.apache.catalina.core.ApplicationContext log
信息: ContextListener: contextInitialized()
2018-4-12 16:05:52 org.apache.catalina.core.ApplicationContext log
信息: SessionListener: contextInitialized()
2018-4-12 16:05:52 org.apache.catalina.core.ApplicationContext log
信息: ContextListener: attributeAdded('org.apache.jasper.compiler.TldLocationsCache', 'org.apache.jasper.compiler.TldLocationsCache@368b1a4f')
2018-4-12 16:05:52 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deployment of web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\examples has finished in 302 ms
2018-4-12 16:05:52 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deploying web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\host-manager
2018-4-12 16:05:53 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deployment of web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\host-manager has finished in 63 ms
2018-4-12 16:05:53 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deploying web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\manager
2018-4-12 16:05:53 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deployment of web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\manager has finished in 53 ms
2018-4-12 16:05:53 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deploying web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\nutzbook
2018-4-12 16:05:54 org.apache.catalina.startup.TaglibUriRule body
信息: TLD skipped. URI: http://java.sun.com/jstl/core is already defined
2018-4-12 16:05:54 org.apache.catalina.startup.TaglibUriRule body
信息: TLD skipped. URI: http://java.sun.com/jstl/fmt is already defined
2018-4-12 16:05:54 org.apache.catalina.startup.TaglibUriRule body
信息: TLD skipped. URI: http://java.sun.com/jstl/sql is already defined
2018-4-12 16:05:54 org.apache.catalina.startup.TaglibUriRule body
信息: TLD skipped. URI: http://java.sun.com/jstl/xml is already defined
2018-4-12 16:05:54 org.apache.catalina.startup.TldConfig execute
信息: 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.
2018-4-12 16:05:54 org.apache.catalina.core.ApplicationContext log
信息: Initializing Shiro environment
2018-04-12 16:05:54,308 org.apache.shiro.web.env.EnvironmentLoader.initEnvironment(EnvironmentLoader.java:128) INFO  - Starting Shiro environment initialization.
2018-04-12 16:05:54,326 org.apache.shiro.web.env.IniWebEnvironment.init(IniWebEnvironment.java:76) DEBUG - Checking any specified config locations.
2018-04-12 16:05:54,326 org.apache.shiro.web.env.IniWebEnvironment.init(IniWebEnvironment.java:81) DEBUG - No INI instance or config locations specified.  Trying default config locations.
2018-04-12 16:05:54,333 org.apache.shiro.io.ResourceUtils.loadFromClassPath(ResourceUtils.java:159) DEBUG - Opening resource from class path [shiro.ini]
2018-04-12 16:05:54,339 org.apache.shiro.config.Ini.load(Ini.java:351) DEBUG - Parsing [main]
2018-04-12 16:05:54,341 org.apache.shiro.config.Ini.load(Ini.java:351) DEBUG - Parsing [urls]
2018-04-12 16:05:54,342 org.apache.shiro.web.env.IniWebEnvironment.getDefaultIni(IniWebEnvironment.java:136) DEBUG - Discovered non-empty INI configuration at location 'classpath:shiro.ini'.  Using for configuration.
2018-04-12 16:05:54,346 org.apache.shiro.config.IniFactorySupport.createInstance(IniFactorySupport.java:122) DEBUG - Creating instance from Ini [sections=main,urls]
2018-04-12 16:05:54,620 org.apache.shiro.realm.AuthorizingRealm.getAuthorizationCacheLazy(AuthorizingRealm.java:234) DEBUG - No authorizationCache instance set.  Checking for a cacheManager...
2018-04-12 16:05:54,621 org.apache.shiro.realm.AuthorizingRealm.getAuthorizationCacheLazy(AuthorizingRealm.java:248) DEBUG - No cache or cacheManager properties have been set.  Authorization cache cannot be obtained.
2018-04-12 16:05:54,622 org.apache.shiro.config.ReflectionBuilder.createNewInstance(ReflectionBuilder.java:296) INFO  - An instance with name 'authc' already exists.  Redefining this object as a new instance of type org.nutz.integration.shiro.SimpleAuthenticationFilter
2018-04-12 16:05:54,714 org.apache.shiro.realm.AuthorizingRealm.getAuthorizationCacheLazy(AuthorizingRealm.java:234) DEBUG - No authorizationCache instance set.  Checking for a cacheManager...
2018-04-12 16:05:54,714 org.apache.shiro.realm.AuthorizingRealm.getAuthorizationCacheLazy(AuthorizingRealm.java:248) DEBUG - No cache or cacheManager properties have been set.  Authorization cache cannot be obtained.
2018-04-12 16:05:54,719 org.apache.shiro.config.IniFactorySupport.createInstance(IniFactorySupport.java:122) DEBUG - Creating instance from Ini [sections=main,urls]
2018-04-12 16:05:54,733 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.createChain(DefaultFilterChainManager.java:127) DEBUG - Creating chain [/rs/*] from String definition [anon]
2018-04-12 16:05:54,734 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.applyChainConfig(DefaultFilterChainManager.java:278) DEBUG - Attempting to apply path [/rs/*] to filter [anon] with config [null]
2018-04-12 16:05:54,737 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.createChain(DefaultFilterChainManager.java:127) DEBUG - Creating chain [/user/logout] from String definition [anon]
2018-04-12 16:05:54,738 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.applyChainConfig(DefaultFilterChainManager.java:278) DEBUG - Attempting to apply path [/user/logout] to filter [anon] with config [null]
2018-04-12 16:05:54,738 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.createChain(DefaultFilterChainManager.java:127) DEBUG - Creating chain [/user/error] from String definition [anon]
2018-04-12 16:05:54,738 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.applyChainConfig(DefaultFilterChainManager.java:278) DEBUG - Attempting to apply path [/user/error] to filter [anon] with config [null]
2018-04-12 16:05:54,738 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.createChain(DefaultFilterChainManager.java:127) DEBUG - Creating chain [/user/login] from String definition [anon]
2018-04-12 16:05:54,738 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.applyChainConfig(DefaultFilterChainManager.java:278) DEBUG - Attempting to apply path [/user/login] to filter [anon] with config [null]
2018-04-12 16:05:54,739 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.createChain(DefaultFilterChainManager.java:127) DEBUG - Creating chain [/user/profile/active/mail] from String definition [anon]
2018-04-12 16:05:54,739 org.apache.shiro.web.filter.mgt.DefaultFilterChainManager.applyChainConfig(DefaultFilterChainManager.java:278) DEBUG - Attempting to apply path [/user/profile/active/mail] to filter [anon] with config [null]
2018-04-12 16:05:54,740 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]
2018-04-12 16:05:54,740 org.apache.shiro.web.env.EnvironmentLoader.initEnvironment(EnvironmentLoader.java:141) INFO  - Shiro environment initialized in 429 ms.
2018-04-12 16:05:54,774 org.nutz.mvc.NutFilter._init(NutFilter.java:85) INFO  - NutFilter[nutz] starting ...
2018-04-12 16:05:54,808 org.nutz.resource.Scans.printLocations(Scans.java:521) DEBUG - Locations count=5 time use 21ms
2018-04-12 16:05:54,949 org.nutz.resource.Scans.printLocations(Scans.java:521) DEBUG - Locations count=29 time use 141ms
2018-04-12 16:05:55,062 org.nutz.castor.Castors.reload(Castors.java:115) DEBUG - Using 95 castor for Castors
2018-04-12 16:05:55,098 org.nutz.mvc.config.AbstractNutConfig.createLoading(AbstractNutConfig.java:59) DEBUG - Loading by class org.nutz.mvc.impl.NutLoading
2018-04-12 16:05:55,100 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:55) INFO  - Nutz Version : 1.r.62 
2018-04-12 16:05:55,100 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:56) INFO  - Nutz.Mvc[nutz] is initializing ...
2018-04-12 16:05:55,100 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:60) DEBUG - Web Container Information:
2018-04-12 16:05:55,102 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:61) DEBUG -  - Default Charset : UTF-8
2018-04-12 16:05:55,102 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:62) DEBUG -  - Current . path  : E:\nutztomcat\tomcat\apache-tomcat-7.0.73\bin\.
2018-04-12 16:05:55,102 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:63) DEBUG -  - Java Version    : 1.6.0_13
2018-04-12 16:05:55,102 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:64) DEBUG -  - File separator  : \
2018-04-12 16:05:55,102 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:65) DEBUG -  - Timezone        : Asia/Shanghai
2018-04-12 16:05:55,102 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:66) DEBUG -  - OS              : Windows Vista amd64
2018-04-12 16:05:55,103 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:67) DEBUG -  - ServerInfo      : Apache Tomcat/7.0.73
2018-04-12 16:05:55,103 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:68) DEBUG -  - Servlet API     : 3.0
2018-04-12 16:05:55,103 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:73) DEBUG -  - ContextPath     : /nutzbook
2018-04-12 16:05:55,103 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:74) DEBUG -  - context.tempdir : E:\nutztomcat\tomcat\apache-tomcat-7.0.73\work\Catalina\localhost\nutzbook
2018-04-12 16:05:55,103 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:75) DEBUG -  - MainModule      : net.wendal.nutzbook.MainModule
2018-04-12 16:05:55,103 org.nutz.mvc.impl.NutLoading.createContext(NutLoading.java:235) DEBUG - >> app.root = E:/nutztomcat/tomcat/apache-tomcat-7.0.73/webapps/nutzbook
2018-04-12 16:05:55,106 org.nutz.mvc.impl.NutLoading.createIoc(NutLoading.java:376) DEBUG - @IocBy(type=org.nutz.mvc.ioc.provider.ComboIocProvider, args=["*js", "ioc/", "*anno", "net.wendal.nutzbook", "*tx", "*quartz"],init=[])
2018-04-12 16:05:55,176 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 2 resource by src( ioc/ ) , regex( ^(.+[.])(js|json)$ )
2018-04-12 16:05:55,177 org.nutz.ioc.loader.json.JsonLoader.<init>(JsonLoader.java:49) DEBUG - loading [dao.js]
2018-04-12 16:05:55,182 org.nutz.ioc.loader.json.JsonLoader.<init>(JsonLoader.java:49) DEBUG - loading [mail.js]
2018-04-12 16:05:55,185 org.nutz.ioc.loader.json.JsonLoader.<init>(JsonLoader.java:57) DEBUG - Loaded 5 bean define from path=[ioc/] --> [htmlEmail, dataSource, dao, conf, emailAuthenticator]
2018-04-12 16:05:55,202 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 21 resource by src( net/wendal/nutzbook/ ) , regex( ^.+[.]class$ )
2018-04-12 16:05:55,240 org.nutz.ioc.loader.annotation.AnnotationIocLoader.addClass(AnnotationIocLoader.java:76) DEBUG - Found @IocBean : class net.wendal.nutzbook.module.AuthorityModule
2018-04-12 16:05:55,257 org.nutz.ioc.loader.annotation.AnnotationIocLoader.addClass(AnnotationIocLoader.java:76) DEBUG - Found @IocBean : class net.wendal.nutzbook.module.CaptchaModule
2018-04-12 16:05:55,260 org.nutz.ioc.loader.annotation.AnnotationIocLoader.addClass(AnnotationIocLoader.java:76) DEBUG - Found @IocBean : class net.wendal.nutzbook.module.UserModule
2018-04-12 16:05:55,268 org.nutz.ioc.loader.annotation.AnnotationIocLoader.addClass(AnnotationIocLoader.java:76) DEBUG - Found @IocBean : class net.wendal.nutzbook.module.UserProfileModule
2018-04-12 16:05:55,273 org.nutz.ioc.loader.annotation.AnnotationIocLoader.addClass(AnnotationIocLoader.java:76) DEBUG - Found @IocBean : class net.wendal.nutzbook.quartz.job.CleanNonActiveUserJob
2018-04-12 16:05:55,275 org.nutz.ioc.loader.annotation.AnnotationIocLoader.addClass(AnnotationIocLoader.java:76) DEBUG - Found @IocBean : class net.wendal.nutzbook.service.AuthorityServiceImpl
2018-04-12 16:05:55,275 org.nutz.ioc.loader.annotation.AnnotationIocLoader.addClass(AnnotationIocLoader.java:76) DEBUG - Found @IocBean : class net.wendal.nutzbook.service.EmailServiceImpl
2018-04-12 16:05:55,277 org.nutz.ioc.loader.annotation.AnnotationIocLoader.addClass(AnnotationIocLoader.java:76) DEBUG - Found @IocBean : class net.wendal.nutzbook.service.UserService
2018-04-12 16:05:55,281 org.nutz.ioc.loader.annotation.AnnotationIocLoader.<init>(AnnotationIocLoader.java:52) INFO  - Found 8 classes in 1 base-packages!
beans = ["captchaModule", "cleanNonActiveUserJob", "userProfileModule", "userService", "authorityModule", "authorityService", "emailService", "userModule"]
2018-04-12 16:05:55,289 org.nutz.ioc.loader.json.JsonLoader.<init>(JsonLoader.java:40) DEBUG - Loaded 5 bean define from reader --
[txREPEATABLE_READ, txREAD_COMMITTED, txNONE, txSERIALIZABLE, txREAD_UNCOMMITTED]
2018-04-12 16:05:55,292 org.nutz.ioc.loader.combo.ComboIocLoader.createIocLoader(ComboIocLoader.java:110) DEBUG - found quartz -- org.nutz.integration.quartz.QuartzIocLoader
2018-04-12 16:05:55,296 org.nutz.ioc.loader.json.JsonLoader.<init>(JsonLoader.java:57) DEBUG - Loaded 0 bean define from path=[] --> []
2018-04-12 16:05:55,303 org.nutz.ioc.impl.NutIoc.<init>(NutIoc.java:98) INFO  - NutIoc init begin ...
2018-04-12 16:05:55,306 org.nutz.ioc.impl.NutIoc.<init>(NutIoc.java:115) INFO  - ... NutIoc init complete
2018-04-12 16:05:55,311 org.nutz.mvc.impl.NutLoading.evalUrlMapping(NutLoading.java:159) INFO  - Build URL mapping by org.nutz.mvc.impl.UrlMappingImpl ...
2018-04-12 16:05:55,316 org.nutz.mvc.impl.NutLoading.createViewMakers(NutLoading.java:366) DEBUG - @Views(DefaultViewMaker.class)
2018-04-12 16:05:55,330 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 1 resource by src( mvc/nutzbook-mvc-chain.js ) , regex( ^(.+[.])(js|json)$ )
2018-04-12 16:05:55,336 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"
   }
}
2018-04-12 16:05:55,336 org.nutz.mvc.impl.NutLoading.createChainMaker(NutLoading.java:263) DEBUG - @ChainBy(org.nutz.mvc.impl.NutActionChainMaker)
2018-04-12 16:05:55,341 org.nutz.mvc.impl.Loadings.scanModules(Loadings.java:154) DEBUG - module class location 'file:/E:/nutztomcat/tomcat/apache-tomcat-7.0.73/webapps/nutzbook/WEB-INF/classes/'
2018-04-12 16:05:55,341 org.nutz.mvc.impl.Loadings.scanModuleInPackage(Loadings.java:184) DEBUG -  > scan 'net.wendal.nutzbook'
2018-04-12 16:05:55,352 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 21 resource by src( net/wendal/nutzbook/ ) , regex( ^.+[.]class$ )
2018-04-12 16:05:55,355 org.nutz.mvc.impl.Loadings.checkModule(Loadings.java:199) DEBUG -    >> add 'net.wendal.nutzbook.module.AuthorityModule'
2018-04-12 16:05:55,356 org.nutz.mvc.impl.Loadings.checkModule(Loadings.java:199) DEBUG -    >> add 'net.wendal.nutzbook.module.CaptchaModule'
2018-04-12 16:05:55,356 org.nutz.mvc.impl.Loadings.checkModule(Loadings.java:199) DEBUG -    >> add 'net.wendal.nutzbook.module.UserModule'
2018-04-12 16:05:55,356 org.nutz.mvc.impl.Loadings.checkModule(Loadings.java:199) DEBUG -    >> add 'net.wendal.nutzbook.module.UserProfileModule'
2018-04-12 16:05:55,439 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/admin/authority/user/update' >> (AuthorityModule.java:37).updateUser  : void       | @Ok(void ) @Fail(jsp:jsp.500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 16:05:55,450 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/get'         >> (UserProfileModule.java:58).get       : UserProfile | @Ok(json:full) @Fail(jsp:jsp.500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 16:05:55,451 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/'            >> (UserProfileModule.java:148).index    : UserProfile | @Ok(jsp:jsp.user.profile) @Fail(jsp:jsp.500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 16:05:55,453 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/update'      >> (UserProfileModule.java:73).update    : void       | @Ok(void ) @Fail(jsp:jsp.500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 16:05:55,467 org.nutz.filepool.NutFilePool.<init>(NutFilePool.java:23) INFO  - Init file-pool by: E:/nutztomcat/tomcat/apache-tomcat-7.0.73/webapps/nutzbook/WEB-INF/tmp/user_avatar [20000]
2018-04-12 16:05:55,469 org.nutz.filepool.NutFilePool.<init>(NutFilePool.java:37) DEBUG - file-pool.home: 'E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\nutzbook\WEB-INF\tmp\user_avatar'
2018-04-12 16:05:55,470 org.nutz.filepool.NutFilePool.<init>(NutFilePool.java:66) INFO  - file-pool.cursor: 0
2018-04-12 16:05:55,477 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/avatar'      >> (UserProfileModule.java:106).uploadAvatar : void       | @Ok(>>:/user/profile) @Fail(jsp:jsp.500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 16:05:55,481 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/avatar'      >> (UserProfileModule.java:136).readAvatar : Object     | @Ok(raw:jpg) @Fail(jsp:jsp.500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 16:05:55,482 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/active/mail' >> (UserProfileModule.java:157).activeMail : Object     | @Ok(json:full) @Fail(jsp:jsp.500) | by 1 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 16:05:55,484 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/profile/active/mail' >> (UserProfileModule.java:184).activeMailCallback : String     | @Ok(raw  ) @Fail(jsp:jsp.500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 16:05:55,486 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/captcha/next'             >> (CaptchaModule.java:23).next          : BufferedImage | @Ok(raw:png) @Fail(jsp:jsp.500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 16:05:55,554 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/add'                 >> (UserModule.java:82).add              : Object     | @Ok(json:{locked:'password|salt',ignoreNull:true}) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 16:05:55,555 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/count'               >> (UserModule.java:48).count            : int        | @Ok(json:{locked:'password|salt',ignoreNull:true}) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 16:05:55,557 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/delete'              >> (UserModule.java:105).delete          : Object     | @Ok(json:{locked:'password|salt',ignoreNull:true}) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 16:05:55,564 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/query'               >> (UserModule.java:117).query           : Object     | @Ok(json:{locked:'password|salt',ignoreNull:true}) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 16:05:55,565 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/'                    >> (UserModule.java:130).index           : void       | @Ok(jsp:jsp.user.login) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 16:05:55,566 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/update'              >> (UserModule.java:94).update           : Object     | @Ok(json:{locked:'password|salt',ignoreNull:true}) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 16:05:55,567 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/login'               >> (UserModule.java:58).login            : Object     | @Ok(json:{locked:'password|salt',ignoreNull:true}) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 16:05:55,568 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/logout'              >> (UserModule.java:76).logout           : void       | @Ok(>>:/user/) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 16:05:55,569 org.nutz.mvc.impl.UrlMappingImpl.print(UrlMappingImpl.java:146) DEBUG -    '/user/login'               >> (UserModule.java:135).loginPage       : void       | @Ok(jsp:jsp.user.login) @Fail(http:500) | by 0 Filters | (I:UTF-8/O:UTF-8)
2018-04-12 16:05:55,569 org.nutz.mvc.impl.NutLoading.evalUrlMapping(NutLoading.java:217) INFO  - Found 18 module methods
2018-04-12 16:05:55,569 org.nutz.mvc.impl.NutLoading.evalLocalization(NutLoading.java:303) DEBUG - Localization: org.nutz.mvc.impl.NutMessageLoader('msg/')  dft<zh-CN>
2018-04-12 16:05:55,573 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 1 resource by src( msg/ ) , regex( ^.+[.]properties$ )
2018-04-12 16:05:55,573 org.nutz.mvc.impl.NutMessageLoader.load(NutMessageLoader.java:27) DEBUG - Load Messages in 1 resource : [[File[E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\nutzbook\WEB-INF\classes\msg\zh-CN\user.properties]]]
2018-04-12 16:05:55,574 org.nutz.mvc.impl.NutMessageLoader.load(NutMessageLoader.java:95) DEBUG - Message Loaded, size = 2
2018-04-12 16:05:55,577 org.nutz.mvc.impl.NutLoading.createSessionProvider(NutLoading.java:410) INFO  - SessionBy --> org.nutz.integration.shiro.ShiroSessionProvider@2a7a289
2018-04-12 16:05:55,577 org.nutz.mvc.impl.NutLoading.evalSetup(NutLoading.java:271) INFO  - Setup application...
2018-04-12 16:05:55,579 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'dao'<interface org.nutz.dao.Dao>
2018-04-12 16:05:55,581 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
2018-04-12 16:05:55,582 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=dao
2018-04-12 16:05:55,582 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=dao
2018-04-12 16:05:55,586 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:161) DEBUG - Found IocObject(dao) in JsonLoader(paths=[ioc/])
2018-04-12 16:05:55,586 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'dao'<interface org.nutz.dao.Dao>
2018-04-12 16:05:55,597 org.nutz.ioc.aop.impl.DefaultMirrorFactory.getMirror(DefaultMirrorFactory.java:70) DEBUG - Load class org.nutz.dao.impl.NutDao without AOP
2018-04-12 16:05:55,598 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'dao' to [app] 
2018-04-12 16:05:55,600 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'dataSource'<>
2018-04-12 16:05:55,600 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=dataSource
2018-04-12 16:05:55,600 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=dataSource
2018-04-12 16:05:55,611 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:161) DEBUG - Found IocObject(dataSource) in JsonLoader(paths=[ioc/])
2018-04-12 16:05:55,612 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'dataSource'<>
2018-04-12 16:05:55,636 org.nutz.ioc.aop.impl.DefaultMirrorFactory.getMirror(DefaultMirrorFactory.java:70) DEBUG - Load class com.alibaba.druid.pool.DruidDataSource without AOP
2018-04-12 16:05:55,636 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'dataSource' to [app] 
2018-04-12 16:05:55,639 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'conf'<>
2018-04-12 16:05:55,639 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=conf
2018-04-12 16:05:55,639 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=conf
2018-04-12 16:05:55,654 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:161) DEBUG - Found IocObject(conf) in JsonLoader(paths=[ioc/])
2018-04-12 16:05:55,655 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'conf'<>
2018-04-12 16:05:55,656 org.nutz.ioc.aop.impl.DefaultMirrorFactory.getMirror(DefaultMirrorFactory.java:70) DEBUG - Load class org.nutz.ioc.impl.PropertiesProxy without AOP
2018-04-12 16:05:55,656 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'conf' to [app] 
2018-04-12 16:05:55,698 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 3 resource by src( custom/ ) , regex( ^.+[.]properties$ )
2018-04-12 16:05:55,698 org.nutz.ioc.impl.PropertiesProxy.setPaths(PropertiesProxy.java:113) DEBUG - load properties from File[E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\nutzbook\WEB-INF\classes\custom\cron.properties]
2018-04-12 16:05:55,698 org.nutz.ioc.impl.PropertiesProxy.setPaths(PropertiesProxy.java:113) DEBUG - load properties from File[E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\nutzbook\WEB-INF\classes\custom\db.properties]
2018-04-12 16:05:55,699 org.nutz.ioc.impl.PropertiesProxy.setPaths(PropertiesProxy.java:113) DEBUG - load properties from File[E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\nutzbook\WEB-INF\classes\custom\mail.properties]
2018-04-12 16:05:55,982 com.alibaba.druid.pool.DruidDataSource.init(DruidDataSource.java:715) INFO  - {dataSource-1} inited
2018-04-12 16:05:55,983 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'dataSource'<>
2018-04-12 16:05:56,189 org.nutz.dao.jdbc.Jdbcs.<clinit>(Jdbcs.java:90) DEBUG - Jdbcs init complete
2018-04-12 16:05:56,189 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
2018-04-12 16:05:56,426 org.nutz.dao.impl.DaoSupport.setDataSource(DaoSupport.java:188) DEBUG - select expert : org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert
2018-04-12 16:05:56,433 org.nutz.dao.impl.DaoSupport$1.invoke(DaoSupport.java:199) DEBUG - JDBC Driver --> mysql-connector-java-5.1.37 ( Revision: 09940f05b4c98150f352e787a2549f11a2e9da93 )
2018-04-12 16:05:56,434 org.nutz.dao.impl.DaoSupport$1.invoke(DaoSupport.java:200) DEBUG - JDBC Name   --> MySQL Connector Java
2018-04-12 16:05:56,434 org.nutz.dao.impl.DaoSupport$1.invoke(DaoSupport.java:202) DEBUG - JDBC URL    --> jdbc:mysql://127.0.0.1:3306/nutzbook
2018-04-12 16:05:56,555 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:206) DEBUG - Mysql : character_set_client=utf8
2018-04-12 16:05:56,555 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:206) DEBUG - Mysql : character_set_connection=utf8
2018-04-12 16:05:56,556 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:206) DEBUG - Mysql : character_set_database=utf8
2018-04-12 16:05:56,556 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:206) DEBUG - Mysql : character_set_filesystem=binary
2018-04-12 16:05:56,556 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:206) DEBUG - Mysql : character_set_results=
2018-04-12 16:05:56,557 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:206) DEBUG - Mysql : character_set_server=utf8
2018-04-12 16:05:56,557 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:206) DEBUG - Mysql : character_set_system=utf8
2018-04-12 16:05:56,557 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:206) DEBUG - Mysql : character_sets_dir=D:\mysql\share\charsets\
2018-04-12 16:05:56,558 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:213) DEBUG - Mysql : binlog_format=STATEMENT
2018-04-12 16:05:56,559 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:220) DEBUG - Mysql : database=nutzbook
2018-04-12 16:05:56,560 org.nutz.dao.impl.jdbc.mysql.MysqlJdbcExpert.checkDataSource(MysqlJdbcExpert.java:226) DEBUG - Mysql : user=root@localhost
2018-04-12 16:05:56,603 org.nutz.dao.impl.DaoSupport.setDataSource(DaoSupport.java:221) DEBUG - Database info --> MYSQL:[MySQL - 5.5.56]
2018-04-12 16:05:56,697 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 21 resource by src( net/wendal/nutzbook/ ) , regex( ^.+[.]class$ )
2018-04-12 16:05:56,710 org.nutz.dao.impl.sql.run.NutDaoExecutor.printSQL(NutDaoExecutor.java:388) DEBUG - SELECT COUNT(*) FROM t_user 
2018-04-12 16:05:56,713 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'nutQuartzCronJobFactory'<class org.nutz.integration.quartz.NutQuartzCronJobFactory>
2018-04-12 16:05:56,714 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=nutQuartzCronJobFactory
2018-04-12 16:05:56,714 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=nutQuartzCronJobFactory
2018-04-12 16:05:56,715 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:161) DEBUG - Found IocObject(nutQuartzCronJobFactory) in QuartzIocLoader@1301331859
2018-04-12 16:05:56,715 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'nutQuartzCronJobFactory'<class org.nutz.integration.quartz.NutQuartzCronJobFactory>
2018-04-12 16:05:56,716 org.nutz.ioc.aop.impl.DefaultMirrorFactory.getMirror(DefaultMirrorFactory.java:70) DEBUG - Load class org.nutz.integration.quartz.NutQuartzCronJobFactory without AOP
2018-04-12 16:05:56,717 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'nutQuartzCronJobFactory' to [app] 
2018-04-12 16:05:56,722 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'scheduler'<>
2018-04-12 16:05:56,722 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=scheduler
2018-04-12 16:05:56,722 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=scheduler
2018-04-12 16:05:56,723 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:161) DEBUG - Found IocObject(scheduler) in QuartzIocLoader@1301331859
2018-04-12 16:05:56,723 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'scheduler'<>
2018-04-12 16:05:56,723 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'scheduler' to [app] 
2018-04-12 16:05:56,764 org.quartz.impl.StdSchedulerFactory.instantiate(StdSchedulerFactory.java:1172) INFO  - Using default implementation for ThreadExecutor
2018-04-12 16:05:56,783 org.quartz.core.SchedulerSignalerImpl.<init>(SchedulerSignalerImpl.java:61) INFO  - Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
2018-04-12 16:05:56,784 org.quartz.core.QuartzScheduler.<init>(QuartzScheduler.java:240) INFO  - Quartz Scheduler v.2.2.3 created.
2018-04-12 16:05:56,785 org.quartz.simpl.RAMJobStore.initialize(RAMJobStore.java:155) INFO  - RAMJobStore initialized.
2018-04-12 16:05:56,786 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.

2018-04-12 16:05:56,786 org.quartz.impl.StdSchedulerFactory.instantiate(StdSchedulerFactory.java:1327) INFO  - Quartz scheduler 'NutzbookScheduler' initialized from default resource file in Quartz package: 'quartz.properties'
2018-04-12 16:05:56,787 org.quartz.impl.StdSchedulerFactory.instantiate(StdSchedulerFactory.java:1331) INFO  - Quartz scheduler version: 2.2.3
2018-04-12 16:05:56,787 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'jobFactory'<>
2018-04-12 16:05:56,787 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=jobFactory
2018-04-12 16:05:56,787 org.nutz.ioc.loader.map.MapLoader.load(MapLoader.java:67) DEBUG - Loading define for name=jobFactory
2018-04-12 16:05:56,789 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:161) DEBUG - Found IocObject(jobFactory) in QuartzIocLoader@1301331859
2018-04-12 16:05:56,789 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'jobFactory'<>
2018-04-12 16:05:56,791 org.nutz.ioc.aop.impl.DefaultMirrorFactory.getMirror(DefaultMirrorFactory.java:70) DEBUG - Load class org.nutz.integration.quartz.NutQuartzJobFactory without AOP
2018-04-12 16:05:56,791 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'jobFactory' to [app] 
2018-04-12 16:05:56,836 org.quartz.core.QuartzScheduler.setJobFactory(QuartzScheduler.java:2311) INFO  - JobFactory set to: org.nutz.integration.quartz.NutQuartzJobFactory@f9a11e4
2018-04-12 16:05:56,836 org.quartz.core.QuartzScheduler.start(QuartzScheduler.java:575) INFO  - Scheduler NutzbookScheduler_$_NON_CLUSTERED started.
2018-04-12 16:05:56,837 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'conf'<>
2018-04-12 16:05:56,837 org.nutz.integration.quartz.NutQuartzCronJobFactory.init(NutQuartzCronJobFactory.java:35) DEBUG - job define name=net.wendal.nutzbook.quartz.job.CleanNonActiveUserJob cron=0 0/2 * * * ?
2018-04-12 16:05:56,850 org.nutz.integration.quartz.NutQuartzCronJobFactory.init(NutQuartzCronJobFactory.java:28) DEBUG - found cron job packages = net.wendal.nutzbook.quartz.job
2018-04-12 16:05:56,853 org.nutz.resource.Scans.scan(Scans.java:274) DEBUG - Found 1 resource by src( net/wendal/nutzbook/quartz/job/ ) , regex( ^.+[.]class$ )
2018-04-12 16:05:56,854 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'authorityService'<interface net.wendal.nutzbook.service.AuthorityService>
2018-04-12 16:05:56,854 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:177) DEBUG - 	 >> Load definition name=authorityService
2018-04-12 16:05:56,854 org.nutz.ioc.loader.combo.ComboIocLoader.load(ComboIocLoader.java:161) DEBUG - Found IocObject(authorityService) in AnnotationIocLoader(packages=[net.wendal.nutzbook])
2018-04-12 16:05:56,854 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:209) DEBUG - 	 >> Make...'authorityService'<interface net.wendal.nutzbook.service.AuthorityService>
2018-04-12 16:05:56,854 org.nutz.ioc.aop.impl.DefaultMirrorFactory.getMirror(DefaultMirrorFactory.java:70) DEBUG - Load class net.wendal.nutzbook.service.AuthorityServiceImpl without AOP
2018-04-12 16:05:56,854 org.nutz.ioc.impl.ScopeContext.save(ScopeContext.java:64) DEBUG - Save object 'authorityService' to [app] 
2018-04-12 16:05:56,860 org.nutz.ioc.impl.NutIoc.get(NutIoc.java:151) DEBUG - Get 'dao'<interface org.nutz.dao.Dao>
2018-04-12 16:05:56,868 org.nutz.dao.impl.sql.run.NutDaoExecutor.printSQL(NutDaoExecutor.java:388) DEBUG - SELECT * FROM t_user  WHERE name=?
    |     1 |
    |-------|
    | admin |
  For example:> "SELECT * FROM t_user  WHERE name='admin'"
2018-04-12 16:05:56,885 org.nutz.dao.impl.sql.run.NutDaoExecutor.printSQL(NutDaoExecutor.java:388) DEBUG - SELECT * FROM t_role  WHERE name=?
    |     1 |
    |-------|
    | admin |
  For example:> "SELECT * FROM t_role  WHERE name='admin'"
2018-04-12 16:05:56,894 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:125) ERROR - Error happend during start serivce!
java.lang.NullPointerException
	at net.wendal.nutzbook.service.AuthorityServiceImpl.checkBasicRoles(AuthorityServiceImpl.java:29)
	at net.wendal.nutzbook.MainSetup.init(MainSetup.java:36)
	at org.nutz.mvc.impl.NutLoading.evalSetup(NutLoading.java:274)
	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:91)
	at org.nutz.mvc.NutFilter.init(NutFilter.java:69)
	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:4958)
	at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5652)
	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:145)
	at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:899)
	at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:875)
	at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:652)
	at org.apache.catalina.startup.HostConfig.deployDirectory(HostConfig.java:1260)
	at org.apache.catalina.startup.HostConfig$DeployDirectory.run(HostConfig.java:2002)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
	at java.util.concurrent.FutureTask.run(FutureTask.java:138)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:619)
2018-04-12 16:05:56,896 org.nutz.mvc.impl.NutLoading.load(NutLoading.java:127) ERROR - try to depose ioc
2018-04-12 16:05:56,898 org.nutz.ioc.impl.NutIoc.depose(NutIoc.java:255) INFO  - org.nutz.ioc.impl.NutIoc@483658151 is closing. startup date [18-04-12 16:05:55.303]
2018-04-12 16:05:56,898 org.nutz.ioc.impl.ScopeContext.clear(ScopeContext.java:108) DEBUG - Depose object 'authorityService' ...
2018-04-12 16:05:56,898 org.nutz.ioc.impl.ScopeContext.clear(ScopeContext.java:108) DEBUG - Depose object 'jobFactory' ...
2018-04-12 16:05:56,898 org.nutz.ioc.impl.ScopeContext.clear(ScopeContext.java:108) DEBUG - Depose object 'scheduler' ...
2018-04-12 16:05:56,899 org.quartz.core.QuartzScheduler.shutdown(QuartzScheduler.java:694) INFO  - Scheduler NutzbookScheduler_$_NON_CLUSTERED shutting down.
2018-04-12 16:05:56,899 org.quartz.core.QuartzScheduler.standby(QuartzScheduler.java:613) INFO  - Scheduler NutzbookScheduler_$_NON_CLUSTERED paused.
2018-04-12 16:05:56,900 org.quartz.simpl.SimpleThreadPool.shutdown(SimpleThreadPool.java:328) DEBUG - Shutting down threadpool...
2018-04-12 16:05:56,900 org.quartz.simpl.SimpleThreadPool.shutdown(SimpleThreadPool.java:395) DEBUG - Shutdown of threadpool complete.
2018-04-12 16:05:56,900 org.quartz.core.QuartzScheduler.shutdown(QuartzScheduler.java:771) INFO  - Scheduler NutzbookScheduler_$_NON_CLUSTERED shutdown complete.
2018-04-12 16:05:56,900 org.nutz.ioc.impl.ScopeContext.clear(ScopeContext.java:108) DEBUG - Depose object 'nutQuartzCronJobFactory' ...
2018-04-12 16:05:56,900 org.nutz.ioc.impl.ScopeContext.clear(ScopeContext.java:108) DEBUG - Depose object 'conf' ...
2018-04-12 16:05:56,901 org.nutz.ioc.impl.ScopeContext.clear(ScopeContext.java:108) DEBUG - Depose object 'dao' ...
2018-04-12 16:05:56,901 org.nutz.ioc.impl.ScopeContext.clear(ScopeContext.java:113) DEBUG - Depose object 'dataSource' ...
2018-04-12 16:05:56,906 com.alibaba.druid.pool.DruidDataSource.close(DruidDataSource.java:1444) INFO  - {dataSource-1} closed
2018-04-12 16:05:56,906 org.nutz.ioc.impl.NutIoc.depose(NutIoc.java:262) INFO  - org.nutz.ioc.impl.NutIoc@483658151 is deposed. startup date [18-04-12 16:05:55.303]
2018-4-12 16:05:56 org.apache.catalina.core.StandardContext filterStart
严重: Exception starting filter nutz
org.nutz.mvc.LoadingException: java.lang.NullPointerException
	at org.nutz.mvc.LoadingException$FC$9a86caf9ff5d3b587784fcdf555a4a7d.invoke(LoadingException.java)
	at org.nutz.lang.born.AbstractConstructorBorning.call(AbstractConstructorBorning.java:25)
	at org.nutz.lang.born.ConstructorBorning.born(ConstructorBorning.java:19)
	at org.nutz.lang.born.BornContext.doBorn(BornContext.java:60)
	at org.nutz.lang.Mirror.born(Mirror.java:990)
	at org.nutz.lang.Lang.wrapThrow(Lang.java:200)
	at org.nutz.mvc.impl.NutLoading.load(NutLoading.java:135)
	at org.nutz.mvc.ActionHandler.<init>(ActionHandler.java:19)
	at org.nutz.mvc.NutFilter._init(NutFilter.java:91)
	at org.nutz.mvc.NutFilter.init(NutFilter.java:69)
	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:4958)
	at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5652)
	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:145)
	at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:899)
	at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:875)
	at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:652)
	at org.apache.catalina.startup.HostConfig.deployDirectory(HostConfig.java:1260)
	at org.apache.catalina.startup.HostConfig$DeployDirectory.run(HostConfig.java:2002)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
	at java.util.concurrent.FutureTask.run(FutureTask.java:138)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:619)
Caused by: java.lang.NullPointerException
	at net.wendal.nutzbook.service.AuthorityServiceImpl.checkBasicRoles(AuthorityServiceImpl.java:29)
	at net.wendal.nutzbook.MainSetup.init(MainSetup.java:36)
	at org.nutz.mvc.impl.NutLoading.evalSetup(NutLoading.java:274)
	at org.nutz.mvc.impl.NutLoading.load(NutLoading.java:121)
	... 20 more
2018-4-12 16:05:56 org.apache.catalina.core.StandardContext startInternal
严重: One or more Filters failed to start. Full details will be found in the appropriate container log file
2018-4-12 16:05:56 org.apache.catalina.core.StandardContext startInternal
严重: Context [/nutzbook] startup failed due to previous errors
2018-4-12 16:05:56 org.apache.catalina.core.ApplicationContext log
信息: Cleaning up Shiro Environment
2018-4-12 16:05:56 org.apache.catalina.loader.WebappClassLoaderBase clearReferencesJdbc
严重: The web application [/nutzbook] registered the JDBC driver [com.alibaba.druid.proxy.DruidDriver] but failed to unregister it when the web application was stopped. To prevent a memory leak, the JDBC Driver has been forcibly unregistered.
2018-4-12 16:05:56 org.apache.catalina.loader.WebappClassLoaderBase clearReferencesJdbc
严重: The web application [/nutzbook] registered the JDBC driver [com.mysql.jdbc.Driver] but failed to unregister it when the web application was stopped. To prevent a memory leak, the JDBC Driver has been forcibly unregistered.
2018-4-12 16:05:56 org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
严重: The web application [/nutzbook] appears to have started a thread named [Abandoned connection cleanup thread] but has failed to stop it. This is very likely to create a memory leak.
2018-4-12 16:05:56 org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
严重: The web application [/nutzbook] appears to have started a thread named [NutzbookScheduler_Worker-1] but has failed to stop it. This is very likely to create a memory leak.
2018-4-12 16:05:56 org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
严重: The web application [/nutzbook] appears to have started a thread named [NutzbookScheduler_Worker-2] but has failed to stop it. This is very likely to create a memory leak.
2018-4-12 16:05:56 org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
严重: The web application [/nutzbook] appears to have started a thread named [NutzbookScheduler_Worker-3] but has failed to stop it. This is very likely to create a memory leak.
2018-4-12 16:05:56 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deployment of web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\nutzbook has finished in 3,857 ms
2018-4-12 16:05:56 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deploying web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\ROOT
2018-4-12 16:05:56 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deployment of web application directory E:\nutztomcat\tomcat\apache-tomcat-7.0.73\webapps\ROOT has finished in 55 ms
2018-4-12 16:05:56 org.apache.coyote.AbstractProtocol start
信息: Starting ProtocolHandler ["http-apr-8080"]
2018-4-12 16:05:57 org.apache.coyote.AbstractProtocol start
信息: Starting ProtocolHandler ["ajp-apr-8009"]
2018-4-12 16:05:57 org.apache.catalina.startup.Catalina start
信息: Server startup in 4779 ms
2018-04-12 16:05:57,269 org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:612) DEBUG - WorkerThread is shut down.
2018-04-12 16:05:57,269 org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:612) DEBUG - WorkerThread is shut down.
2018-04-12 16:05:57,269 org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:612) DEBUG - WorkerThread is shut down.

看到了 ，是adminRole =null， 调用addRole（）返回的还是null。addRole（）实现接口必须实现的方法
@wendal

package net.wendal.nutzbook.service;

import java.util.List;

import org.nutz.dao.Chain;
import org.nutz.dao.Cnd;
import org.nutz.dao.Dao;
import org.nutz.dao.entity.Record;
import org.nutz.ioc.loader.annotation.Inject;
import org.nutz.ioc.loader.annotation.IocBean;

import net.wendal.nutzbook.bean.Permission;
import net.wendal.nutzbook.bean.Role;
import net.wendal.nutzbook.bean.User;

@IocBean(name = "authorityService")
public class AuthorityServiceImpl implements AuthorityService{
	
	@Inject
	private Dao dao;
	@Override
	 public void checkBasicRoles(User admin) {
	        // 检查一下admin的权限
	        Role adminRole = dao.fetch(Role.class, "admin");
	        if (adminRole == null) {
	            adminRole = addRole("admin");
	        }
	        // admin账号必须存在与admin组
	        if (0 == dao.count("t_user_role", Cnd.where("u_id", "=", admin.getId()).and("role_id", "=", adminRole.getId()))) {
	            dao.insert("t_user_role", Chain.make("u_id", admin.getId()).add("role_id", adminRole.getId()));
	        }
	        // admin组必须有authority:* 也就是权限管理相关的权限
	        List<Record> res = dao.query("t_role_permission", Cnd.where("role_id", "=", adminRole.getId()));
	        OUT: for (Permission permission : dao.query(Permission.class, Cnd.where("name", "like", "authority:%").or("name", "like", "user:%"), null)) {
	            for (Record re : res) {
	                if (re.getInt("permission_id") == permission.getId())
	                    continue OUT;
	            }
	            dao.insert("t_role_permission", Chain.make("role_id", adminRole.getId()).add("permission_id", permission.getId()));
	        };
	    }
	@Override
	public void initFormPackage(String pkg) {
		
	}
	@Override
	public void addPermission(String permission) {
		
	}
	@Override
	public Role addRole(String role) {
		return null;
	}

}

就只要修改addRole()，add这个用户就行了是么？ 大佬
@wendal

那个问题我跳过了 ，解决现在运行的错误。