原创

记一次服务器日志查看及BUG维护

公司一个小项目,好长时间没维护,然后某天接到反馈(问题已出现很久),某项功能有问题,看了下数据库记录已经过去了将近一个月吧,只能查日志了。

先看看最后1000行的日志信息有没有有用的东西

tail -n 1000 catalina.out

并没有找到有用的信息,因为时间有点长,只能慢慢往上找

tail -n 2000 catalina.out |head -n 1000

查看最后2000行中的前1000行。

另外在附一些常用的查看日志、文件的命令

# 从第11行开始显示,但不包括最后3行
head -n -3 catalina.out |tail -n +11
# 显示前20行,但从第11行开始
head -n 20 catalina.out |tail -n +11 
# 显示除最后3行以外的所有行,但只显示最后10行
head -n -3 catalina.out |tail -n 10 
# 显示前20行中的后10行
head -n 20 catalina.out |tail -n 10 
# 从第11行开始显示,但只显示前10行
tail -n +11 catalina.out |head -n 10 
# 从第11行开始显示,但不包括最后3行
tail -n +11 catalina.out |head -n -3
# 显示最后13行中的前10行
tail -n 13 catalina.out |head -n 10 
# 显示最后13行中除末尾的3行以外的前10行
tail -n 13 catalina.out |head -n -3

(我是用的putty连的服务器)因为putty命令控制台的缓冲区并不大(也可能是因为我不知道怎么修改罢了),如果查询过多信息,可能会显示不全,所以只能一点点的找,着实是麻烦了一点,最后决定将日志文件下载下来本地查看,也便于记录。

scp /xx/catalina.out root@host:/var/

将本机的文件复制到host对应的服务器的var目录下(原谅我用这么笨的方法,只是因为我们公司服务器没有开ftp),然后用xftp登录host对应的服务器,然后将日志文件下载到本地。

好吧,日志已经到手(才80多M,真心不多),粗略的看了下,发现了几点问题,记录一下。

一:Tomcat认证异常

WARNING: An attempt was made to authenticate the locked user "crux"
Feb 28, 2017 8:14:54 PM org.apache.catalina.realm.LockOutRealm filterLockedAccounts
...
Feb 08, 2017 11:42:26 PM org.apache.catalina.realm.LockOutRealm filterLockedAccounts
WARNING: An attempt was made to authenticate the locked user "admin"
Feb 08, 2017 11:42:26 PM org.apache.catalina.realm.LockOutRealm filterLockedAccounts
WARNING: An attempt was made to authenticate the locked user "tomcat"
Feb 08, 2017 11:42:27 PM org.apache.catalina.realm.LockOutRealm filterLockedAccounts
WARNING: An attempt was made to authenticate the locked user "manager"
...

如上所示,这种信息还有很多很多,粗略估计得有好几十页。看来我们服务器也被闲得无聊的人盯上了(或者这只是网上一些无聊的扫描器搞的)

在查看日志的时候还发现一个有意思的地方就是:

Feb 28, 2017 8:15:04 PM org.apache.catalina.realm.LockOutRealm filterLockedAccounts
WARNING: An attempt was made to authenticate the locked user "chongchujianghu"

这是大佬啊,重出江湖(手动滑稽)。致大佬:你接着出吧,不过悠着点,别出到粪坑里,我还得去捞你。

为了省事(当然,这也是最有效的一个办法),我直接将webapps下的文件夹全部删除了,瞬间还世界一片安静。

总结:

tomcat服务器webapps下的默认文件夹没特殊要求就都删掉吧,本地怎么玩都无所谓,正式线上没有谁会开放这些东西。

二:HttpClient异常关闭

org.apache.http.ConnectionClosedException: Premature end of Content-Length delimited message body (expected: 28969; received: 17704
at org.apache.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:184)
at org.apache.http.conn.EofSensorInputStream.read(EofSensorInputStream.java:138)
at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:283)
at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:325)
at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:177)
at java.io.InputStreamReader.read(InputStreamReader.java:184)
at java.io.Reader.read(Reader.java:140)
at org.apache.http.util.EntityUtils.toString(EntityUtils.java:233)
at cn.com.icbc.xceImpl.xtas(FxImpl.java:97)
at cn.com.icbc.xceImpl.rxnfo(FXSxpl.java:78)
at cn.com.icbc.xceImpl.cxcts(FXSxpl.java:67)
at cn.com.icbc.web.Fxller.getNxist(Fxller.java:49)
at cn.com.icbc.web.Fxntroller.ajaxst(Fxoller.java:45)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:222)
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:137)
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:110)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:775)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:705)
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:959)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:893)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:965)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:867)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:755)
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:841)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:848)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:684)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1496)
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:85)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1476)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:499)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:557)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:231)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1086)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:428)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1020)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
at org.eclipse.jetty.server.Server.handle(Server.java:370)
at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:494)
at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:971)
at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:1033)
at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:644)
at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235)
at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:667)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:52)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
at java.lang.Thread.run(Thread.java:745)

根据异常描述可以,HttpClient异常关闭,预期response body的长度为28969,实际只接受到17704,也就是说,还没接收完链接就断了。

网上有人说“程序员显式封闭了连接”,我觉得这句话是个病句,应该说是程序显式封闭了连接,(不能什么锅都往我们程序金刚身上甩啊)。这个在日志中是偶发的,所以我个人倾向于这是因为接口异常导致返回的数据长度异常增大所造成的。只能先观察观察。

三:java.lang.NoClassDefFoundError异常

14:05:00,134 DefaultQuartzScheduler_Worker-10 org.quartz.core.JobRunShell - Job DEFAULT.cn_com_icbc_xtinitial threw an unhandled Exception: 
java.lang.NoClassDefFoundError: Could not initialize class com.vanstone.mail.conf.PropertiesHostConf
at cn.com.icbc.xxx.sendx(AppointxImpl.java:395)
at cn.com.icbc.xtJob.execute(SendxJob.java:50)
at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)
at org.springframework.context.support.AbstractRefreshableApplicationContext.getBeanFactory(AbstractRefreshableApplicationContext.java:170)
at org.springframework.context.support.AbstractApplicationContext.getBean(AbstractApplicationContext.java:975)
at cn.com.icbc.framework.spring.SpringContextHolder.getBean(SpringContextHolder.java:57)
at cn.com.icbc.framework.spring.ServiceManagerFactory.getService(ServiceManagerFactory.java:48)
at cn.com.icbc.x.SendxJob.execute(SendxJob.java:37)
at org.springframework.context.support.AbstractRefreshableApplicationContext.getBeanFactory(AbstractRefreshableApplicationContext.java:170)	at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)
at org.springframework.context.support.AbstractApplicationContext.getBean(AbstractApplicationContext.java:975)
at cn.com.icbc.framework.spring.SpringContextHolder.getBean(SpringContextHolder.java:57)
at cn.com.icbc.framework.spring.ServiceManagerFactory.getService(ServiceManagerFactory.java:48)
at cn.com.icbc.x.SendxJob.execute(SendxJob.java:37)
at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)

     NoClassDefFoundError错误的发生,是因为Java虚拟机在编译时能找到合适的类,而在运行时不能找到合适的类导致的错误。例如在运行时我们想调用某个类的方法或者访问这个类的静态成员的时候,发现这个类不可用,此时Java虚拟机就会抛出NoClassDefFoundError错误。与ClassNotFoundException的不同在于,这个错误发生只在运行时需要加载对应的类不成功,而不是编译时发生。很多Java开发者很容易在这里把这两个错误搞混。简单总结就是,NoClassDefFoundError发生在编译时对应的类可用,而运行时在Java的classpath路径中,对应的类不可用导致的错误。    

    NoClassDefFoundError也可能由于类的静态初始化模块错误导致,当你的类执行一些静态初始化模块操作,如果初始化模块抛出异常,那些依赖这个类的其他类会抛出NoClassDefFoundError的错误。

    我们程序中这个异常的原因就是因为静态代码块出错造成的。因为是前后台分离的项目,定时任务写到了core模块中,web和admin依赖core模块,但是有一个定时任务只适用于admin项目,同时需要加载配置文件,web项目中并没有放该配置文件,所以造成代码异常。

总结:

1.分模块发开、分业务开发

2.遵循最小职能化原则,谁需要谁调用,并且尽量少的开放此类代码

3.做好测试工作

四:Mysql异常

ERROR 2017-03-09 17:35:16,283 BoneCP-pool-watch-thread com.jolbox.bonecp.BoneCP - Failed to acquire connection to jdbc:mysql://127.0.0.1:3306/icbc. Sleeping for 7000 ms. Attempts left: 4
com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.
...

原因分析

(1)大量数据访问情况下,mysql connection连接有可能失效 

(2)长时间不妨问,connection会失效 

第一种解决办法:

将mysql回收空闲连接的时间变长,mysql默认回收时间是8小时(show global variables like 'wait_timeout';),可以在mysql目录下的my.cnf中增加下面配置,扩大回收空闲连接的时间。

vim /etc/mysql/my.cnf #路径根据自己服务器中的mysql安装位置来

然后找到[mysqld] ,在其下方添加如下配置

wait_timeout=31536000 
interactive_timeout=31536000

添加完后,需要重启mysql

service mysql restart

也可以直接在mysql命令窗口中执行一下命令修改

set global wait_timeout=31536000 ;
set global interactive_timeout=31536000 ;

注意:在命令行中修改只是临时解决方案, 重启mysql之后就会失效,所以建议在配置文件中修改

第二种解决办法:

使用JDBC URL中使用autoReconnect属性,url添加

&autoReconnect=true&failOverReadOnly=false&maxReconnects=10

五:Too many connections异常

com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Data source rejected establishment of connection,  message from server: "Too many connections"

出现这个问题的原因一般就是mysql链接之后没有close,当大量的connect之后,就会出现这个异常。mysql的默认链接数100个(可见官方文档:https://dev.mysql.com/doc/refman/5.7/en/too-many-connections.html,或者通过以下命令查看)

mysql> show global variables like '%max_connections%';
+-----------------+-------+
| Variable_name   | Value |
+-----------------+-------+
| max_connections | 100   |
+-----------------+-------+
1 row in set (0.00 sec)

可以通过修改my.cnf配置文件解决

vim /etc/mysql/my.cnf #路径根据自己服务器中的mysql安装位置来

然后找到[mysqld] ,在其下方添加如下配置

max_connections=3600

也可以通过mysql命令行修改

set global max_connections = 3600;

注:这种方式在重启mysql服务之后会失效

参考资料

http://blog.csdn.net/gisredevelopment/article/details/41744467

http://blog.csdn.net/cynhafa/article/details/19676865

http://blog.csdn.net/jamesjxin/article/details/46606307


正文到此结束