Windows 服务 程序开发之异常日志
事情概况 ： 昨天Windows服务程序里面的linq to sql 报了个错误,如下
“System.Data.Linq.ChangeConflictException: 找不到行或行已更改。”
这个错本身属于并发的问题，可是我这里要说的却是另外一回事。发现这个问题以后，便把服务程序停掉，然后再起动，结果还是一样的，这个错仍然存在，最后把服务程序卸载了，然后再安装一次就没有问题了。这样一个奇怪的问题，写一篇日志把它记录下来,作为教训,服务程序每秒执行一次，一个小小的bug就会引起重大影响，这个问题导致短时间内出现了1000多封拉圾邮件，让邮件服务程序承受不了。
程序大致是这样的
Windows服务程序大致如下
代码
using System;
using System.Data.SqlClient;
using System.Linq;
using System.ServiceProcess;
using System.Timers;
using log4net;
namespace Avantouch.Platform.WinServices.Topup
{
internal partial class TopupService3 : ServiceBase
{
private static readonly ILog SubmitLog = LogManager.GetLogger("DFSubmitLog");
private static readonly ILog VerifyLog = LogManager.GetLogger("DFVerifyLog");
private static PlatformDataContext _submitDataContext;
private static PlatformDataContext _verifyDataContext;
private static PlatformDataContext _NewOrderDataContext;
private readonly Timer _submitTimer;
private readonly Timer _verifyTimer;
#endregion
public TopupService3()
{
InitializeComponent();
_submitDataContext = new PlatformDataContext(Settings.Default.ServicesConnectionString);
_verifyDataContext = new PlatformDataContext(Settings.Default.ServicesConnectionString);
_submitTimer = new Timer(1000);
_submitTimer.Elapsed += SubmitTimerElapsed;
_verifyTimer = new Timer(5 * 60 * 1000);
_verifyTimer.Elapsed += VerifyTimerElapsed;
}
protected override void OnStart(string[] args)
{
_submitTimer.Start();
_verifyTimer.Start();
}
protected override void OnStop()
{
_submitTimer.Stop();
_verifyTimer.Stop();
}
internal void SubmitTimerElapsed(object sender, ElapsedEventArgs e)
{
_submitTimer.Stop();
try
{
IQueryable<Order> orders = from t in _submitDataContext.Orders
join t0 in _submitDataContext.Product on t.ProductId equals t0.ProductId
where t.CategoryId == 1 && t0.SupplierId == 5 && t.Submitted == false && t.Deleted
== "0"
select t;
Order record = orders.FirstOrDefault();
if (record != null)
{
//处理程序
_submitDataContext.SubmitChanges();
}
}
catch (SqlException sqlException)
{
SubmitLog.Error("数据库错误", sqlException);
Alert("0003", "1");
}
catch (Exception exception)
{
SubmitLog.Error("异常错误", exception);
Alert("0004", "1");
}
finally
{
_submitTimer.Start();
}
}
internal void VerifyTimerElapsed(object sender, ElapsedEventArgs e)
{
_verifyTimer.Stop();
VerifyLog.Info("--------------------------------------------------");
VerifyLog.InfoFormat("德丰充值查询验证服务时间：{0}信息输出......", System.DateTime.Now);
try
{
IQueryable<Order> orders = from t in _verifyDataContext.Orders
join t0 in _verifyDataContext.Product on t.ProductId equals t0.ProductId
where t.CategoryId == 1 && t0.SupplierId == 5 && t.Submitted && !t.Verified &&
t.Deleted == "0" && t.SubmitTime.Value.AddMinutes(5) < DateTime.Now
select t;
foreach (Order record in orders)
{
//处理程序
_verifyDataContext.SubmitChanges();
}
}
catch (SqlException sqlException)
{
//邮件
VerifyLog.Error("数据库错误", sqlException);
Alert("0003", "2");
}
catch (Exception exception)
{
//TODO：邮件
VerifyLog.Error("异常错误", exception);
Alert("0004", "2");
}
finally
{
_verifyTimer.Start();
}
}
}
}
using System.Data.SqlClient;
using System.Linq;
using System.ServiceProcess;
using System.Timers;
using log4net;
namespace Avantouch.Platform.WinServices.Topup
{
internal partial class TopupService3 : ServiceBase
{
private static readonly ILog SubmitLog = LogManager.GetLogger("DFSubmitLog");
private static readonly ILog VerifyLog = LogManager.GetLogger("DFVerifyLog");
private static PlatformDataContext _submitDataContext;
private static PlatformDataContext _verifyDataContext;
private static PlatformDataContext _NewOrderDataContext;
private readonly Timer _submitTimer;
private readonly Timer _verifyTimer;
#endregion
public TopupService3()
{
InitializeComponent();
_submitDataContext = new PlatformDataContext(Settings.Default.ServicesConnectionString);
_verifyDataContext = new PlatformDataContext(Settings.Default.ServicesConnectionString);
_submitTimer = new Timer(1000);
_submitTimer.Elapsed += SubmitTimerElapsed;
_verifyTimer = new Timer(5 * 60 * 1000);
_verifyTimer.Elapsed += VerifyTimerElapsed;
}
protected override void OnStart(string[] args)
{
_submitTimer.Start();
_verifyTimer.Start();
}
protected override void OnStop()
{
_submitTimer.Stop();
_verifyTimer.Stop();
}
internal void SubmitTimerElapsed(object sender, ElapsedEventArgs e)
{
_submitTimer.Stop();
try
{
IQueryable<Order> orders = from t in _submitDataContext.Orders
join t0 in _submitDataContext.Product on t.ProductId equals t0.ProductId
where t.CategoryId == 1 && t0.SupplierId == 5 && t.Submitted == false && t.Deleted
== "0"
select t;
Order record = orders.FirstOrDefault();
if (record != null)
{
//处理程序
_submitDataContext.SubmitChanges();
}
}
catch (SqlException sqlException)
{
SubmitLog.Error("数据库错误", sqlException);
Alert("0003", "1");
}
catch (Exception exception)
{
SubmitLog.Error("异常错误", exception);
Alert("0004", "1");
}
finally
{
_submitTimer.Start();
}
}
internal void VerifyTimerElapsed(object sender, ElapsedEventArgs e)
{
_verifyTimer.Stop();
VerifyLog.Info("--------------------------------------------------");
VerifyLog.InfoFormat("德丰充值查询验证服务时间：{0}信息输出......", System.DateTime.Now);
try
{
IQueryable<Order> orders = from t in _verifyDataContext.Orders
join t0 in _verifyDataContext.Product on t.ProductId equals t0.ProductId
where t.CategoryId == 1 && t0.SupplierId == 5 && t.Submitted && !t.Verified &&
t.Deleted == "0" && t.SubmitTime.Value.AddMinutes(5) < DateTime.Now
select t;
foreach (Order record in orders)
{
//处理程序
_verifyDataContext.SubmitChanges();
}
}
catch (SqlException sqlException)
{
//邮件
VerifyLog.Error("数据库错误", sqlException);
Alert("0003", "2");
}
catch (Exception exception)
{
//TODO：邮件
VerifyLog.Error("异常错误", exception);
Alert("0004", "2");
}
finally
{
_verifyTimer.Start();
}
}
}
}
程序里有两个timer，都是查找出记录，处理完了以后再更新，其中_submitTimer是一秒钟更新一次，而_verifyTimer是5分钟后再查询记录更新处理，正常情况下两个timer不会同时处理同一条记录，即linq to sql 不会发生并发的问题。但是如果submitTimer里的程序出了异常，延迟了5分钟，异致两个timer会同时处理同一条记录，linq to sql 导致了并发冲突.。
结果submitTimer处理死循环当中，系统的工作日志如下
代码
2010-12-21 17:27:27,023 [10] INFO DFSubmitLog - ==================================================
2010-12-21 17:27:27,023 [10] INFO DFSubmitLog - 开始提交序号为353770的订单......
2010-12-21 17:27:27,042 [10] DEBUG DFSubmitLog - 数据库字段已更新......
2010-12-21 17:37:57,792 [10] ERROR DFSubmitLog - 异常错误
System.Data.Linq.ChangeConflictException: 找不到行或行已更改。
在 System.Data.Linq.ChangeProcessor.SubmitChanges(ConflictMode failureMode)
在 System.Data.Linq.DataContext.SubmitChanges(ConflictMode failureMode)
在 Avantouch.Platform.WinServices.Topup.TopupService3.SubmitTimerElapsed(Object sender, ElapsedEventArgs e)
2010-12-21 17:37:57,793 [10] INFO DFSubmitLog - 开始下发报警邮件通知......
2010-12-21 17:37:57,803 [10] INFO DFSubmitLog - 邮件已下发......
2010-12-21 17:37:58,891 [9] INFO DFSubmitLog - ==================================================
2010-12-21 17:37:58,891 [9] INFO DFSubmitLog - 开始提交序号为353773的订单......
2010-12-21 17:37:58,909 [9] ERROR DFSubmitLog - 异常错误
System.Data.Linq.ChangeConflictException: 找不到行或行已更改。
在 System.Data.Linq.ChangeProcessor.SubmitChanges(ConflictMode failureMode)
在 System.Data.Linq.DataContext.SubmitChanges(ConflictMode failureMode)
在 Avantouch.Platform.WinServices.Topup.TopupService3.SubmitTimerElapsed(Object sender, ElapsedEventArgs e)
2010-12-21 17:37:58,910 [9] INFO DFSubmitLog - 开始下发报警邮件通知......
2010-12-21 17:37:58,919 [9] INFO DFSubmitLog - 邮件已下发......
2010-12-21 17:38:00,013 [9] INFO DFSubmitLog - ==================================================
2010-12-21 17:38:00,013 [9] INFO DFSubmitLog - 开始提交序号为353773的订单......
2010-12-21 17:38:00,036 [9] ERROR DFSubmitLog - 异常错误
System.Data.Linq.ChangeConflictException: 找不到行或行已更改。
在 System.Data.Linq.ChangeProcessor.SubmitChanges(ConflictMode failureMode)
在 System.Data.Linq.DataContext.SubmitChanges(ConflictMode failureMode)
在 Avantouch.Platform.WinServices.Topup.TopupService3.SubmitTimerElapsed(Object sender, ElapsedEventArgs e)
2010-12-21 17:38:00,036 [9] INFO DFSubmitLog - 开始下发报警邮件通知......
2010-12-21 17:38:00,041 [9] INFO DFSubmitLog - 邮件已下发......
2010-12-21 17:38:01,121 [9] INFO DFSubmitLog - ==================================================
2010-12-21 17:38:01,121 [9] INFO DFSubmitLog - 开始提交序号为353773的订单......
2010-12-21 17:38:01,140 [9] ERROR DFSubmitLog - 异常错误
System.Data.Linq.ChangeConflictException: 找不到行或行已更改。
在 System.Data.Linq.ChangeProcessor.SubmitChanges(ConflictMode failureMode)
在 System.Data.Linq.DataContext.SubmitChanges(ConflictMode failureMode)
在 Avantouch.Platform.WinServices.Topup.TopupService3.SubmitTimerElapsed(Object sender, ElapsedEventArgs e)
2010-12-21 17:38:01,140 [9] INFO DFSubmitLog - 开始下发报警邮件通知......
2010-12-21 17:38:01,146 [9] INFO DFSubmitLog - 邮件已下发......
2010-12-21 17:38:02,230 [9] INFO DFSubmitLog - ==================================================
这是这样一直处于死循环当中了。这时候把服务停了，然后启动，还是出错，日志记录如下
代码
2010-12-21 18:04:27,848 [8] INFO DFSubmitLog - 服务已停止......
2010-12-21 18:04:29,156 [9] INFO DFSubmitLog - 服务已启动......
2010-12-21 18:04:30,241 [9] INFO DFSubmitLog - ==================================================
2010-12-21 18:04:30,241 [9] INFO DFSubmitLog - 开始提交序号为353773的订单......
2010-12-21 18:04:30,261 [9] ERROR DFSubmitLog - 异常错误
System.Data.Linq.ChangeConflictException: 找不到行或行已更改。
在 System.Data.Linq.ChangeProcessor.SubmitChanges(ConflictMode failureMode)
在 System.Data.Linq.DataContext.SubmitChanges(ConflictMode failureMode)
在 Avantouch.Platform.WinServices.Topup.TopupService3.SubmitTimerElapsed(Object sender, ElapsedEventArgs e)
2010-12-21 18:04:30,262 [9] INFO DFSubmitLog - 开始下发报警邮件通知......
2010-12-21 18:04:30,268 [9] INFO DFSubmitLog - 邮件已下发......
2010-12-21 18:04:31,351 [9] INFO DFSubmitLog - ==================================================
2010-12-21 18:04:31,351 [9] INFO DFSubmitLog - 开始提交序号为353773的订单......
2010-12-21 18:04:31,371 [9] ERROR DFSubmitLog - 异常错误
System.Data.Linq.ChangeConflictException: 找不到行或行已更改。
在 System.Data.Linq.ChangeProcessor.SubmitChanges(ConflictMode failureMode)
在 System.Data.Linq.DataContext.SubmitChanges(ConflictMode failureMode)
在 Avantouch.Platform.WinServices.Topup.TopupService3.SubmitTimerElapsed(Object sender, ElapsedEventArgs e)
2010-12-21 18:04:31,372 [9] INFO DFSubmitLog - 开始下发报警邮件通知......
2010-12-21 18:04:31,378 [9] INFO DFSubmitLog - 邮件已下发......
2010-12-21 18:04:32,474 [6] INFO DFSubmitLog - ==================================================
2010-12-21 18:04:29,156 [9] INFO DFSubmitLog - 服务已启动......
2010-12-21 18:04:30,241 [9] INFO DFSubmitLog - ==================================================
2010-12-21 18:04:30,241 [9] INFO DFSubmitLog - 开始提交序号为353773的订单......
2010-12-21 18:04:30,261 [9] ERROR DFSubmitLog - 异常错误
System.Data.Linq.ChangeConflictException: 找不到行或行已更改。
在 System.Data.Linq.ChangeProcessor.SubmitChanges(ConflictMode failureMode)
在 System.Data.Linq.DataContext.SubmitChanges(ConflictMode failureMode)
在 Avantouch.Platform.WinServices.Topup.TopupService3.SubmitTimerElapsed(Object sender, ElapsedEventArgs e)
2010-12-21 18:04:30,262 [9] INFO DFSubmitLog - 开始下发报警邮件通知......
2010-12-21 18:04:30,268 [9] INFO DFSubmitLog - 邮件已下发......
2010-12-21 18:04:31,351 [9] INFO DFSubmitLog - ==================================================
2010-12-21 18:04:31,351 [9] INFO DFSubmitLog - 开始提交序号为353773的订单......
2010-12-21 18:04:31,371 [9] ERROR DFSubmitLog - 异常错误
System.Data.Linq.ChangeConflictException: 找不到行或行已更改。
在 System.Data.Linq.ChangeProcessor.SubmitChanges(ConflictMode failureMode)
在 System.Data.Linq.DataContext.SubmitChanges(ConflictMode failureMode)
在 Avantouch.Platform.WinServices.Topup.TopupService3.SubmitTimerElapsed(Object sender, ElapsedEventArgs e)
2010-12-21 18:04:31,372 [9] INFO DFSubmitLog - 开始下发报警邮件通知......
2010-12-21 18:04:31,378 [9] INFO DFSubmitLog - 邮件已下发......
2010-12-21 18:04:32,474 [6] INFO DFSubmitLog - ==================================================
结果把服务卸载了，然后再安装问题便没了.遇到这个问题，然后网上查了一下，也咨询了一相，只能考虑linq to sql 的资源没有释放掉了。这个问题的根源在于submitTimer里的异常，导致两个timer同时处理一条记录，目前先处理掉这个根源问题
有关linq to sql 的资源释放问是，可参考以下链接的文章
http://www.cnblogs.com/kirinboy/archive/2010/01/04/dispose-datacontext-or-not.html
http://blog.darkthread.net/blogs/darkthreadtw/archive/2009/10/19/linq-to-sql-connection-issue.aspx
有关解决linq to sql 并发冲突的话，可参考以下文章
http://www.cnblogs.com/sunnyfong/archive/2008/09/25/1298829.html