Troubleshooting Subscriptions: Part II, Using the Reporting Services Trace Log File
Hey There – About a year ago I posted this blog about troubleshooting subscriptions. Since then I’ve received quite a few questions and come across more subscription problems in our production Reporting Services server that identified a few gaps in my previous posting, so I thought I would elaborate more on the subject here.
To recap a few key points from before:
When you create a subscription several things are added to the RS server:
- A row is placed in the Subscriptions table…
- A row is placed in the Schedule and ReportSchedule tables…
- A SQL Server Agent job is created…
When the subscription runs several things happen:
- The SQL Server Agent job fires and puts a row in the Event table…
- The RS server service has a limited number of threads (2 per CPU) that poll the Event table…
- When it finds an event, it puts a row in the Notifications table and starts processing…
That blog content is a good start at isolating the issue to one of the key sources of problems, but since then I’ve found that many of the subscription problems I deal with fall into the “starts processing… ” point above. I often find my investigation of these problems go well beyond my “this can usually be tested by running the report manually” recommendation, so I’ll attempt to give this area better justice here by sharing some of my experience with the trace log file.
The Trace Log: More Than You Ever Needed or Wanted to Know About Your RS Server
The trace log file is created in a folder under your SQL Server installation path. In my machine this happens to be:
C:\Program Files\Microsoft SQL Server\MSRS10_50.MSSQLSERVER\Reporting Services\LogFiles
for a default install of SQL Server 2008 R2. Previous versions of SQL Server will be named differently, but your’s should be in a similar location. A quick search of the SQL Server books online will give you some configuration options that allow you to control how big the files get, how long they are kept, and the type of information and activities that are logged to the file and so on. For a detault RS installation, these files will be limited to a max size of 32mb and “rollover” to a new file if that size is exceeded, and old files will be deleted after 14 days. The file will also be closed and recreated each time the RS server is recycled, which by default will happen every day at midnight. The name of the trace log file will be similar to "ReportServerService__02_15_2010_12_56_37.log", and the “02_15_2010_12_56_37” portion will indicate the date/time the file was created in the “MM_DD_YYYY_HH_mm_SS” format. If you happen to be researching a problem that just ocurred, you can just view the newest file, otherwise you will have to find the file that contains the range of information including the entries you are looking for, based on the timestamps in the file names and the entries in the file.
A common response when people ask for help with a report problem is, “What did you see in the trace log file?”. However, it can be a bit daunting the first time you open the file, and it can take some practice to get good at reading it effectively. The first problem is the sheer bulk of content that is logged in the multi-mb file, and the next problem is the cryptic nature of the multi-mb content.
I’d like to help you make sense of this information to diagnose and fix subscription and other Reporting Services problems.
This file contains a multitude of information about practically every action, operation, process etc that occurs in the RS server. Some of them are for internal processing, and some are related to the processing of reports, subscriptions or other user initiated or defined operations. For example:
library!WindowsService_9!12c0!02/15/2010-02:00:16:: e ERROR: Throwing Microsoft.ReportingServices.Diagnostics.Utilities.LogonFailedException: Logon attempt for user 'username' failed., Microsoft.ReportingServices.Diagnostics.Utilities.LogonFailedException: Log on failed. Ensure the user name and password are correct. ---> System.ComponentModel.Win32Exception: Logon failure: unknown user name or bad password
There are several aspects of this entry that are worth noting. First of all, each "entry" is prefixed by a set of fields similar to:
processing!WindowsService_9!12c0!02/15/2010-02:00:16::
Which can be parsed down to:
"Processing": The library within the RS server
"WindowsService_9":The AppDomain within the library
"12c0": The thread within the Appdomain
"02/15/2010-02:00:16": The timestamp when the information was logged
Secondly, most entries contain the strings “I Info”, “w Warn”, or “e Error”; the “e Error” entries are usually the most interesting and valuable, yet the other entries around the error entries can also contain interesting information. The remaining parts of the entry line describe what occurred in the server.
And finally, as you will see below, there is sometimes a set of callstack frames following (what I call) the regular entry lines, and they typically have the form:
at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)
These entries refer to the code inside the Reporting Services server and its referenced libraries. They will not typically be of much value to you in researching report or subscription errors, but if you do happen to experience other types of RS server problems (or yes, even server bugs we may have unfortunately missed in testing), including the callstack with an explanation of the problem will be very helpful for us or CSS to understand more about the problem.
Locating Subscription Entries in the Trace Log File
Step 1: Get the Schedule Id
A good general approach to researching problems in the trace log file is to determine when a problem occurred, find the entries in the log file around that time, and just start poking around. This can be enough if you have a quiet RS server with very little activity, but an active server can have hundreds of entries within a few minutes, so “poking around” may not be too successful.
The next step would be to get a more precise date/time value for when a problem occurred, this can be obtained from the TimeStart or TimeEnd fields in the ExecutionLog table, or the LastRunTime field of the Subscription table in the catalog database. But again, even with this information, there may still be hundreds of entries in the trace log file at key times (say, 8am) when there is a lot of other successful and unsuccessful subscription or report activity in the server at the same time as the failed subscription.
The key point in isolating subscriptions further goes back to what happens “When a subscription runs”. As I said before, when a subscription runs, the status in the subscription table is updated, but I should have added “and entries are placed in the trace log file with the schedule id.” In other words, the key link between a subscription execution and the entries in the trace log file is the schedule id for the subscription. The schedule id must be obtained from the Subscription table, it is not visible via the UI tools, and the query below can help, assuming you understand the legal stuff:
Disclaimer: we do not officially support querying all of the Reporting Services tables mentioned below, the columns and information in them may change in the future.
select
'SubnDesc' = s.Description,
'SubnOwner' = us.UserName,
'LastStatus' = s.LastStatus,
'LastRun' = s.LastRunTime,
'ReportPath' = c.Path,
'ReportModifiedBy' = uc.UserName,
'ScheduleId' = rs.ScheduleId, -- This is what you need
'SubscriptionId' = s.SubscriptionID
from ReportServer.dbo.Subscriptions s
join ReportServer.dbo.Catalog c on c.ItemID = s.Report_OID
join ReportServer.dbo.ReportSchedule rs on rs.SubscriptionID = s.SubscriptionID
join ReportServer.dbo.Users uc on uc.UserID = c.ModifiedByID
join ReportServer.dbo.Users us on us.UserID = s.OwnerId
Step 2: Find That Schedule ID in the Trace Log File
Once you have the schedule id for the subscription, you can look for the value in the trace file to find the entries for that subscription. The good news is that the schedule id is a guid; the only entries you find in the file with that string will be the entries for this subscription.
àSide Note: subscriptions can use either a custom schedule created for that subscription, or they can use a shared schedule. I only use custom schedules, and the examples here assume a custom schedule.
The not-so good news is that if the subscription fired several times within the timeframe of the contents in the trace log file, you will have to find the entry nearest to the one that failed based on the timestamp of the entry.
In my local server, I created a subscription and waited for it to fire. The rows in the Subscription table using the query above told me that my schedule id was “4459bc37-97d5-46c4-bd9d-d1e97e4e1cac”, and the first entry with this guid was:
library!WindowsService_0!1354!02/15/2010-14:51:03:: i INFO: Schedule 4459bc37-97d5-46c4-bd9d-d1e97e4e1cac executed at 02/15/2010 14:51:03.
àSide Note: I’m using the latest and greatest version of Reporting Services in SQL 2008 R2, and my dev partner who helps me with this stuff improved the log file content for subscriptions in this release. Your log file content may be somewhat different, but the approach is the same.
Step 3: Look at the other entries with the same thread in the same time proximity
Based on the entry above with the schedule id, you can see that the thread is “1354”, and searching on that thread, you will see another set of entries similar to:
schedule!WindowsService_0!1354!02/15/2010-14:51:03:: Creating Time based subscription notification for subscription: 41344f16-88e5-43b2-9e6b-1996e210eb6b
library!WindowsService_0!1354!02/15/2010-14:51:03:: i INFO: Schedule 4459bc37-97d5-46c4-bd9d-d1e97e4e1cac execution completed at 02/15/2010 14:51:03.
notification!WindowsService_0!1354!02/15/2010-14:51:03:: i INFO: Handling notification of subscription 41344f16-88e5-43b2-9e6b-1996e210eb6b to report Reportname via delivery provider Report Server FileShare
library!WindowsService_0!1354!02/15/2010-14:51:04:: i INFO: RenderForNewSession('/pathname/reportname’)
You may notice that the subscription id guid is also in the entries here, they can also be used, but in previous versions of RS we only logged the schedule id, so I'm focusing on it here instead.
In this example, the subscription was successful, yeah, big deal, but it is a good start in learning how to find the information when they are not successful. I also used a quiet local report server, so all my entries were literally next to each other in the file making them easy to identify. But again, in our production server, there are a lot of subscriptions firing at common times, so their entries may be spread more broadly throughout the file. Also, be careful to watch the timestamps of the entries for each thread, if the same thread happened to process another subscription later, you need to make sure you don’t associate your current subscription with the entries for the next.
Common Types of Subscription Failures
Now, lets have more fun and look at a couple common types of subscription errors and their trace log file entries.
Invalid logins
In today’s world of defense against hackers (those guys really take the fun out of developing softwareL) the sorry truth is that SQL passwords have to expire. This is the most common cause of recurring problems I see, and they often happen when people forget to update their passwords in all the necessary data sources. In my example here, I changed the password for the data source of the report used by my subscription to be invalid. The error displayed in the subscription table and in Report Manager was simply “An error has occurred during report processing.” which doesn’t tell much, but the entries recorded in the trace log file included a much more useful error:
processing!WindowsService_0!fd8!02/15/2010-20:52:06:: e ERROR: Throwing Microsoft.ReportingServices.ReportProcessing.ReportProcessingException: , Microsoft.ReportingServices.ReportProcessing.ReportProcessingException: Cannot impersonate user for data source 'datasourcename'. ---> Microsoft.ReportingServices.Diagnostics.Utilities.LogonFailedException: Log on failed. ---> System.ComponentModel.Win32Exception: Logon failure: unknown user name or bad password
Report Query Errors
Another common theme I see when users say “my subscription is not working” is, report queries that were successful when the report is created may not always stay that way; they may later return typical TSQL errors indicating deadlocks, query timeouts, divide by zero, invalid casting and so on. In my example, the report was based on a call to a stored procedure, so I changed the procedure name in the report dataset to an invalid name, and when the subscription fired Report Manager still displayed the error “An error has occurred during report processing.”, but the trace file displayed this entry:
subscription!WindowsService_0!fd8!02/15/2010-21:09:08:: i INFO: Microsoft.ReportingServices.Diagnostics.Utilities.RSException: An error has occurred during report processing. ---> Microsoft.ReportingServices.ReportProcessing.ProcessingAbortedException: An error has occurred during report processing. ---> Microsoft.ReportingServices.ReportProcessing.ReportProcessingException: Query execution failed for dataset 'datasetname'. ---> System.Data.SqlClient.SqlException: Could not find stored procedure 'databasename.dbo.badprocname'.
at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)
Data Driven Subscription Errors
Both of the examples above were the result of common report definition problems, and as I alluded to in my other posting, these types of problems could have been found by just running the report locally using a report designer where the errors are returned to the client. This is how I often research problems with the reports I own, because a) I don’t have to hassle with the trace log file, and b) I commonly have to fix the problem using the report designer anyways.
But another recent case I dealt with was related to a data driven subscription. The IT admin of the server knows just enough about Reporting Services to be dangerous, and their response to me (and a large alias of RS people who watch the server) was “Why is the subscription failing when the report runs fine manually? Subscriptions are not working, please fix!”. To make matters worse, the report and subscrition permssions were locked up tight and I couldn't view it in Report Manager. This is a case where you cannot just run the report to see the problem, you have to look in the trace log file. For this example I created a valid data driven subscription, and the entries in the log file were similar to:
library!WindowsService_0!fd8!02/15/2010-21:19:03:: i INFO: Schedule 2fa7246d-c112-496f-969b-680e279413d3 executed at 02/15/2010 21:19:03.
schedule!WindowsService_0!fd8!02/15/2010-21:19:03:: Creating Time based subscription notification for subscription: 3c963022-70b7-4172-926a-f9a045a2d38f
library!WindowsService_0!fd8!02/15/2010-21:19:03:: i INFO: Schedule 2fa7246d-c112-496f-969b-680e279413d3 execution completed at 02/15/2010 21:19:03.
As you may notice, the log file entries for the data driven subscription were in a somewhat different format from regular subscriptions.
To simulate the error, I dropped the table that was used in my data driven subscription query, and the trace log entry was:
library!WindowsService_0!18e4!02/15/2010-21:38:03:: e ERROR: Error processing data driven subscription: System.Data.SqlClient.SqlException: Invalid object name 'dbname.dbo.testtable'.
at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)
Ok, the subscription status I could have queried for this particular error was also “Error: Invalid object name 'dbname.dbo.testtable'.”, but I’m on such a roll with the trace log file I thought I would include it anyways.
File Delivery Errors
As I was creating the subscriptions to demonstrate the log file information for this blog, I have been using file share delivery because my local box is not configured with SMTP to deliver emails, and in the process I mistakenly used the wrong password for the credentials to access the file share in my subscription. The error displayed in Report Manager was “Done: 1 processed of 1 total; 1 errors.”, but the entry in the trace log file was:
subscription!WindowsService_0!fd8!02/15/2010-21:34:10:: i INFO: Error writing file xx.xml to path \\myserver\myshare
Using the Trace Log File to Investigate Other Types of Errors
The errors mentioned above are just a sampling of the types of problems that can affect subscriptions, many are the same as or very similar to the types of errors that affect live report execution outside of subscriptions. I won’t take blog space to cover more here, but there are many other types of problems that can be diagnosed through the trace log file. They can also be investigated using many of the same techniques I mention here, the only difference is that with problems with subscriptions, you start by searching for the schedule id. But for reports, the entries are in a form similar to:
library!WindowsService_0!fd8!02/15/2010-21:34:03:: i INFO: RenderForNewSession('/pathname/reportname')
Problems with data sources are similar to:
processing!WindowsService_0!18e4!02/15/2010-20:50:05:: e ERROR: Throwing Microsoft.ReportingServices.ReportProcessing.ReportProcessingException: , Microsoft.ReportingServices.ReportProcessing.ReportProcessingException: Cannot impersonate user for data source 'datasourcename'. ---> Microsoft.ReportingServices.Diagnostics.Utilities.LogonFailedException: Log on failed. ---> System.ComponentModel.Win32Exception: Logon failure: unknown user name or bad password
The only difference is what you search on in the file.
And finally, many of the techniques I mention here refer to finding a starting location in the file and searching down for the entries with the same thread. Sometimes, the real problem happened before the entry you found, so if you don’t find what you need, you might want to try searching “up” through the previous entries for the thread.
Corellating the Trace Log Files With Other Data
I've mentioned the ExecutionLog table (and its related views) in my other blogs, and my esteemed peer Robert Bruckner covers it thoroughly in his blog here. This information is available in the report server catalog database and it also has a wealth of valuable information about the report executions and other activities in your report server. But when errors are shown there, the only information you have is the status of the report execution, ie "rsProcessingAborted", so you can use the steps above to take the report name and the execution time to search for the real problem in the trace log file.
The opposite is also true, if you happen to be strolling through the log file and come across error entries like those I listed above, you can also go to the ExecutionLog table to see:
- What was executing around the time that the trace log entry was recorded
- Who was executing it and what parameters they used
- Whether it was a subscription or an interactive (live) request
- Was it executed live from a data source or did it come from the cache
and so on. Note that subscription executions themselves are not in the ExecutionLog, only the reports that are run by the subscription are logged there. So if the subscription problem happens before the step where the report is executed, as in the data driven subscription example above, you won't find it in the ExecutionLog. The good news is that you can also cross reference the entries in the trace log file with the Subscriptions table based on the Schedule Id to learn a lot more about the subscription problem.
So Why Can't I QUERY the @@#$% Trace Log File???:(
If you've read my intro blog entry, I'm a database guy. The ever present thought in my mind when I'm searching and scrolling and searching and scrolling through log files is the same question, which I asked the first person who would listen to me about ten seconds after I first opened a trace log file. "Hey, we could write reports against it, make subscriptions on those reports for monitoring, aggregate data over time with cubes and dashboards and this and that and all kinds of other cool database stuff". So if you have these same thoughts, I've got your back.
When I calmed down and turned my hearing back on, the key fact is that we really have to weigh costs of this sort of thing. There is a huuuuge amount of data in the trace log files, and taking the time to log them in a SQL table during report server processing will cause a pretty big hit on the resources of the RS server and its catalog database, not to mention the costs of cleaning up old entries to prevent the catalog database files from filling up the disk and killing the whole server, and a few other issues we probably wouldn't realize and have to address until after it is all in place. We could trim the amount of data sent to the database table, but much of the content really is valuable, so what should we give up?
I did talk to an IS firend about using their features to load the file into the database, he said "Standard format? Check, no problem. Occasional callstacks?...", and that plan fell apart. Finally, I did create a TSQL parser and a snappy database design to process and store it for queries, and my more coding-oriented peers eventually shamed me into doing it with C#. Its pretty cool and useful, but not quite bulletproof enough for prime time yet. I may decide to post this solution at some point in the future, assuming I finish writing performance reviews in time and make space in my deliverables for the next cool release of RS.
Happy Reporting! I hope this helps, please let me know.
Thanks, Dean
As usual, "This blog is provided 'AS IS' with no warranties, and confers no rights."
Comments
Anonymous
August 01, 2011
I just had a subcription schedule which was not suppose to process for 8/1/2011 do just that. I confirmed it in the log that you write about here. The Schedule table is a bit cryptic and I'm frantically trying to determine why it ran when it was not supposed to. I re-created the same schedule (all months except August) on another report and it worked correctly, not processing. Have you heard about this before?Anonymous
October 31, 2011
Yes Just happened to me, in the exact same senario. Report schedule for 10/1/2011 worked, however it was not schedule to run again until 4/1/2012. However, it ran 11/1/2011. Any information out there on this.Anonymous
December 13, 2011
Logparser 2.0 from microsoft might be the tool you want for the log file queryAnonymous
April 12, 2012
Did you ever release your TSQL parser? I am very interested.Anonymous
June 04, 2012
While working through an entirely different issue I found your blog and thought I'd add some value too. If somebody's looking for the native SSRS logs on a SQL 2012 SSRS server that's integrated with SharePoint 2010, the magic location is 'C:Program FilesCommon FilesMicrosoft SharedWeb Server Extensions14WebServicesLogFiles' Now if I could only find the cause of 'e ERROR: Throwing Microsoft.ReportingServices.ReportProcessing.ReportProcessingException: , Microsoft.ReportingServices.ReportProcessing.ReportProcessingException: The specified operation is not valid. ;'Anonymous
June 18, 2014
also, take a look at the ReportServer.ExecutionLogStorage table where status<>'rsSuccess'Anonymous
October 14, 2014
Hi there, I am facing a problem with the subscriptions. We are creating subscriptions automatically via de database. Users can apply setting in one of our source applications and we push the right settings in the SSRS database. This worked fine till users get complaining they don't receive reports. The strange thing is that "old subscription" work fine. Only new created ones don't work anymore. I have checked the logfiles, tables but no solution yet. The subscriptions that don't work have LastStatus=Pending. Any idea how to troubleshoot this one?Anonymous
October 14, 2014
The comment has been removedAnonymous
February 12, 2015
Great Read, I have a subscription which failed, it failed due to an SP failing to create a temp table, then accoording to the executionlog3 retried automatically, I have checked for other subscriptions - there are none it's really wierd.Anonymous
August 11, 2015
Thanks for this article and the other one. It helped me a lot in trouble shooting / understanding SSRS. Somewhere I read that the maximum number of subscription that SSRs Server can handle at a time is 4 times the number of CPUs. I am unable to locate that reference anymore. Question is , is that true ? In a VM situation , if one allots more cpus , then the subscription load can be increased ? Because I see bunching up of subscription in the queue .and so delays in report /subscription completion Any help or hint would be nice.