Monday, March 12, 2012

Inconsistent Subscription Success

Hi,
I've got a production SQL Reporting Services installation and have
created some file share subscriptions for one of the reports.
Sometimes the subscriptions work and sometimes they don't. My customer
has now had enough and wants to have them working all of the time
(unsurprisingly!).
I have spent the whole day testing various things to try to get some
consistency and haven't been able to prove anything. If, for example,
I create 5 new subscriptions (either to run all at the same time or to
run one minute after each other), any number of the subscriptions will
run properly (ie. and will create the file on the file share) -
sometimes none will run, sometimes a few will run, sometimes all five
will run. I have just created eight new subscriptions in an absolutely
identical manner and only one of the eight ran properly (and it wasn't
the first or last one).
I cannot find any error messages anywhere in the system, ie. in event
viewer, in the SQL RS logs, in the SQL logs, etc., and as nothing is
changing on the system - ie. local user rights, NTFS permissions, IIS
permissions, SQL permissions, etc. - I can't work out why the
subscriptions work sometimes and not others.
I've looked through a lot of the Google postings and can see that other
people have similar things.
If anyone can offer any suggestions so that I can get SQL RS to work
properly, please let me know - I'll really appreciate it.
Cheers,
Rich
(MCSE MCSD MCDBA)Hello Richard,
Can you see all the corresponding jobs created for your subscriptions? When
a subscription does not work, can you see that the job in SQL Server Agent is
running or was triggered as expected?
Ricardo.
"richard.warner@.zurich.com" wrote:
> Hi,
> I've got a production SQL Reporting Services installation and have
> created some file share subscriptions for one of the reports.
> Sometimes the subscriptions work and sometimes they don't. My customer
> has now had enough and wants to have them working all of the time
> (unsurprisingly!).
> I have spent the whole day testing various things to try to get some
> consistency and haven't been able to prove anything. If, for example,
> I create 5 new subscriptions (either to run all at the same time or to
> run one minute after each other), any number of the subscriptions will
> run properly (ie. and will create the file on the file share) -
> sometimes none will run, sometimes a few will run, sometimes all five
> will run. I have just created eight new subscriptions in an absolutely
> identical manner and only one of the eight ran properly (and it wasn't
> the first or last one).
> I cannot find any error messages anywhere in the system, ie. in event
> viewer, in the SQL RS logs, in the SQL logs, etc., and as nothing is
> changing on the system - ie. local user rights, NTFS permissions, IIS
> permissions, SQL permissions, etc. - I can't work out why the
> subscriptions work sometimes and not others.
> I've looked through a lot of the Google postings and can see that other
> people have similar things.
> If anyone can offer any suggestions so that I can get SQL RS to work
> properly, please let me know - I'll really appreciate it.
> Cheers,
>
> Rich
> (MCSE MCSD MCDBA)
>|||Hi, Ricardo.
Thanks for your reply.
Yes - the jobs all show in the SQL Server Agent jobs view in Enterprise
Manager. They show as Succeeded (<date> <time>). As SQL server
considers them to have succeeded, there is no entry in the event log.
During some of the testing, I modified one of the jobs (Notification
tab) so that it wrote to the Windows application event log "whenever
the job completes", and all that did was write an entry to the event
log to say the job had completed successfully!
When I look in the Execution Log table of the SQL RS database, I can
see that not all of the subscriptions show there.
When I look in the Subscriptions table of the SQL RS database, I can
see all of the subscriptions, but the ones that didn't work properly
still show a LastRun time of <NULL>.
Cheers,
Rich|||Hello Richard,
It seems that there is a mismatch between the jobs in SQL and the
subscriptions. Have you tried recreating the jobs? Stop the ReportServer
service, then delete all SQL Agent jobs related to reporting services (all
jobs that have category "Report Server"), and then start the ReportServer
service. It will recreate the necessary SQL Agent jobs.
Ricardo.
"richard.warner@.zurich.com" wrote:
> Hi, Ricardo.
> Thanks for your reply.
> Yes - the jobs all show in the SQL Server Agent jobs view in Enterprise
> Manager. They show as Succeeded (<date> <time>). As SQL server
> considers them to have succeeded, there is no entry in the event log.
> During some of the testing, I modified one of the jobs (Notification
> tab) so that it wrote to the Windows application event log "whenever
> the job completes", and all that did was write an entry to the event
> log to say the job had completed successfully!
> When I look in the Execution Log table of the SQL RS database, I can
> see that not all of the subscriptions show there.
> When I look in the Subscriptions table of the SQL RS database, I can
> see all of the subscriptions, but the ones that didn't work properly
> still show a LastRun time of <NULL>.
> Cheers,
>
> Rich
>|||As you suggested, we stopped the ReportServer service, deleted the
Report Server SQL Agent jobs, then restarted the ReportServer service,
and the Report Server jobs were recreated in the SQL Agent. However,
it hasn't helped resolve the problem.
I have just created five new run-once subscriptions - each configured
to run one minute after the last. The first three were successful, the
fourth wasn't, and the fifth was. Looking in the SQL Agent, all of
them show as Succeeded (<date> <time>). Again - all five subscriptions
were created in an absolutely identical manner.
Have you got any other suggestions?
Cheers,
Rich|||Hello Richard,
What is the status of the subscription in the Subscriptions page? Does it
show that all subscription run and all of them were successful?
In the logs, can you see the calls for all five subscriptions?
Ricardo.
"richard.warner@.zurich.com" wrote:
> As you suggested, we stopped the ReportServer service, deleted the
> Report Server SQL Agent jobs, then restarted the ReportServer service,
> and the Report Server jobs were recreated in the SQL Agent. However,
> it hasn't helped resolve the problem.
> I have just created five new run-once subscriptions - each configured
> to run one minute after the last. The first three were successful, the
> fourth wasn't, and the fifth was. Looking in the SQL Agent, all of
> them show as Succeeded (<date> <time>). Again - all five subscriptions
> were created in an absolutely identical manner.
> Have you got any other suggestions?
> Cheers,
>
> Rich
>|||Hi, Ricardo.
Thanks for your quick reply again.
Sorry - I was mistaken in my last mail - three of the subscriptions ran
successfully and two of them didn't (not four and one, as I'd said).
In the Subscriptions page, the three successful subscriptions show as
"File xx.xx was written to xx", and the two unsuccessful subscriptions
show as "New subscription".
Which log are you referring to? If you're referring to the
ReportServer_<date>_<time>.log file in the SQL RS LogFiles directory,
then yes - I can see a line for the creation of each of the five
subscriptions. The line is as follows:
"aspnet_wp!subscription!bf4!<date>-<time>:: Subscription Created for
report /<folder>/<report> at <date>T<time> by <me>"
This line occurs five times and corresponds exactly with the times that
I created the subscriptions.
Cheers,
Rich|||Hello Richard,
If the subscription stays at "New subscription" then it means it hasn't run,
or (I think) something happened and it is retrying. Has the process
dealocked? Are you trying to write the same filename all the time? Is it
possible that there was a sharing violation? In the logs, after the
subscription was queued the first time, can you see whether RS is queing the
two "missing" subscriptions again? Has the status changed in the
Subscriptions page?
Ricardo.
"richard.warner@.zurich.com" wrote:
> Hi, Ricardo.
> Thanks for your quick reply again.
> Sorry - I was mistaken in my last mail - three of the subscriptions ran
> successfully and two of them didn't (not four and one, as I'd said).
> In the Subscriptions page, the three successful subscriptions show as
> "File xx.xx was written to xx", and the two unsuccessful subscriptions
> show as "New subscription".
> Which log are you referring to? If you're referring to the
> ReportServer_<date>_<time>.log file in the SQL RS LogFiles directory,
> then yes - I can see a line for the creation of each of the five
> subscriptions. The line is as follows:
> "aspnet_wp!subscription!bf4!<date>-<time>:: Subscription Created for
> report /<folder>/<report> at <date>T<time> by <me>"
> This line occurs five times and corresponds exactly with the times that
> I created the subscriptions.
> Cheers,
>
> Rich
>|||Hi, Ricardo.
Are you referring to the aspnet_wp.exe process? If so, there are no
events in the event log showing that the process has deadlocked and
been restarted.
Each subscription is created to write to a different file name.
I don't think it's possible that there was a sharing violation. In
each case, the file doesn't exist before the subscription runs and
nothing tries to open the file subsequently.
In the log file, RS isn't queuing the two missing subscriptions again.
The status hasn't changed in the Subscriptions page.
In the ReportServerService_<date>_<time>.log file, I can see the
successful subscriptions being run. These ran today at 13:23, 13:25
and 13:27. The missing ones were scheduled to run at 13:24 and 13:26.
Here is a typical section of the log from the successful subscriptions:
ReportingServicesService!dbpolling!a20!02/11/2005-13:27:04::
EventPolling processing 1 more items. 1 Total items in internal queue.
ReportingServicesService!dbpolling!d64!11/02/2005-13:27:04::
EventPolling processing item ce6bf843-1a37-4c0a-aa76-218284fafc1a
ReportingServicesService!library!d64!11/02/2005-13:27:04:: Schedule
69782008-e708-4927-9eeb-f1640c7ec996 executed at 11/02/2005 13:27:04.
ReportingServicesService!schedule!d64!11/02/2005-13:27:04:: Creating
Time based subscription notification for subscription:
63b17fae-0d44-4d2e-8a75-c0ac68ebd080
ReportingServicesService!library!d64!11/02/2005-13:27:04:: Schedule
69782008-e708-4927-9eeb-f1640c7ec996 execution completed at 11/02/2005
13:27:04.
ReportingServicesService!dbpolling!d64!11/02/2005-13:27:04::
EventPolling finished processing item
ce6bf843-1a37-4c0a-aa76-218284fafc1a
ReportingServicesService!dbpolling!a20!02/11/2005-13:27:04::
NotificationPolling processing 1 more items. 1 Total items in internal
queue.
ReportingServicesService!dbpolling!d64!11/02/2005-13:27:04::
NotificationPolling processing item
ceeebad5-0578-4b59-af37-5fd8305ddbac
ReportingServicesService!library!d64!11/02/2005-13:27:04:: i INFO: Call
to RenderFirst( '/<folder>/<report>' ) !-- this line modified by me in
Google post to hide folder/report name
ReportingServicesService!library!d64!11/02/2005-13:27:06:: i INFO:
Initializing EnableExecutionLogging to 'True' as specified in Server
system properties.
ReportingServicesService!notification!d64!11/02/2005-13:27:06::
Notification ceeebad5-0578-4b59-af37-5fd8305ddbac completed. Success:
True, Status: File E5.pdf was written to \\<server>\<share>,
DeliveryExtension: Report Server FileShare, Report: ARMReport1, Attempt
0 !-- this line modified by me again
ReportingServicesService!dbpolling!d64!11/02/2005-13:27:06::
NotificationPolling finished processing item
ceeebad5-0578-4b59-af37-5fd8305ddbac
I have created 12 more subscriptions running at various intervals (1
minute, 2 minutes, 3 minutes, 5 minutes and 10 minutes) - mixing these
intervals up to see if it's anything to do with how far apart the jobs
are running. I know this is grabbing at straws, but I'm happy to try
anything! :-> I've just realised that the results from these
subscriptions will be in soon, so I'll hold on before posting this and
will include the results ...
New results from 12 subscriptions:
1 - (Time = 15:40) - Didn't run
2 - (Time = 15:41) - Didn't run
3 - (Time = 15:43) - Ran
4 - (Time = 15:45) - Ran
5 - (Time = 15:48) - Didn't run
6 - (Time = 15:50) - Didn't run
7 - (Time = 15:52) - Didn't run
8 - (Time = 15:53) - Ran
9 - (Time = 15:55) - Ran
10 - (Time = 15:58) - Didn't run
11 - (Time = 16:03) - Didn't run
12 - (Time = 16:13) - Didn't run
That seems fairly inconculsive to me!
Any other thoughts?
Cheers,
Rich|||Hello Richard,
I am talking about the process in the database. Are you running the reports
from a stored procedure, or a simple query? If you run the stored procedures
or queries in Query Analyzer at those intervals, does it always run and
return data? Do they deadlock?
Ricardo.
"richard.warner@.zurich.com" wrote:
> Hi, Ricardo.
> Are you referring to the aspnet_wp.exe process? If so, there are no
> events in the event log showing that the process has deadlocked and
> been restarted.
> Each subscription is created to write to a different file name.
> I don't think it's possible that there was a sharing violation. In
> each case, the file doesn't exist before the subscription runs and
> nothing tries to open the file subsequently.
> In the log file, RS isn't queuing the two missing subscriptions again.
> The status hasn't changed in the Subscriptions page.
> In the ReportServerService_<date>_<time>.log file, I can see the
> successful subscriptions being run. These ran today at 13:23, 13:25
> and 13:27. The missing ones were scheduled to run at 13:24 and 13:26.
> Here is a typical section of the log from the successful subscriptions:
> ReportingServicesService!dbpolling!a20!02/11/2005-13:27:04::
> EventPolling processing 1 more items. 1 Total items in internal queue.
> ReportingServicesService!dbpolling!d64!11/02/2005-13:27:04::
> EventPolling processing item ce6bf843-1a37-4c0a-aa76-218284fafc1a
> ReportingServicesService!library!d64!11/02/2005-13:27:04:: Schedule
> 69782008-e708-4927-9eeb-f1640c7ec996 executed at 11/02/2005 13:27:04.
> ReportingServicesService!schedule!d64!11/02/2005-13:27:04:: Creating
> Time based subscription notification for subscription:
> 63b17fae-0d44-4d2e-8a75-c0ac68ebd080
> ReportingServicesService!library!d64!11/02/2005-13:27:04:: Schedule
> 69782008-e708-4927-9eeb-f1640c7ec996 execution completed at 11/02/2005
> 13:27:04.
> ReportingServicesService!dbpolling!d64!11/02/2005-13:27:04::
> EventPolling finished processing item
> ce6bf843-1a37-4c0a-aa76-218284fafc1a
> ReportingServicesService!dbpolling!a20!02/11/2005-13:27:04::
> NotificationPolling processing 1 more items. 1 Total items in internal
> queue.
> ReportingServicesService!dbpolling!d64!11/02/2005-13:27:04::
> NotificationPolling processing item
> ceeebad5-0578-4b59-af37-5fd8305ddbac
> ReportingServicesService!library!d64!11/02/2005-13:27:04:: i INFO: Call
> to RenderFirst( '/<folder>/<report>' ) !-- this line modified by me in
> Google post to hide folder/report name
> ReportingServicesService!library!d64!11/02/2005-13:27:06:: i INFO:
> Initializing EnableExecutionLogging to 'True' as specified in Server
> system properties.
> ReportingServicesService!notification!d64!11/02/2005-13:27:06::
> Notification ceeebad5-0578-4b59-af37-5fd8305ddbac completed. Success:
> True, Status: File E5.pdf was written to \\<server>\<share>,
> DeliveryExtension: Report Server FileShare, Report: ARMReport1, Attempt
> 0 !-- this line modified by me again
> ReportingServicesService!dbpolling!d64!11/02/2005-13:27:06::
> NotificationPolling finished processing item
> ceeebad5-0578-4b59-af37-5fd8305ddbac
> I have created 12 more subscriptions running at various intervals (1
> minute, 2 minutes, 3 minutes, 5 minutes and 10 minutes) - mixing these
> intervals up to see if it's anything to do with how far apart the jobs
> are running. I know this is grabbing at straws, but I'm happy to try
> anything! :-> I've just realised that the results from these
> subscriptions will be in soon, so I'll hold on before posting this and
> will include the results ...
> New results from 12 subscriptions:
> 1 - (Time = 15:40) - Didn't run
> 2 - (Time = 15:41) - Didn't run
> 3 - (Time = 15:43) - Ran
> 4 - (Time = 15:45) - Ran
> 5 - (Time = 15:48) - Didn't run
> 6 - (Time = 15:50) - Didn't run
> 7 - (Time = 15:52) - Didn't run
> 8 - (Time = 15:53) - Ran
> 9 - (Time = 15:55) - Ran
> 10 - (Time = 15:58) - Didn't run
> 11 - (Time = 16:03) - Didn't run
> 12 - (Time = 16:13) - Didn't run
> That seems fairly inconculsive to me!
> Any other thoughts?
> Cheers,
>
> Rich
>|||Hi, Ricardo.
Sorry for the delay in my reply. I've made slight progress in that I
know that one of the two SQL RS IIS servers is causing a problem (I
probably should have said before that we have two SQL RS servers
talking to one SQL RS database). By stopping the ReportServer service
on the second SQL RS server, all of the subscriptions now work (even
though the subscriptions are only configured on one of the servers, and
are only saving files on the same server, etc - so as far as I was
concerned, the second server wasn't involved). I'll look into this
more tomorrow, but for now my solution is just to keep that service
stopped on the second server and lose the resilience that the second
SQL RS server was providing.
Thanks again for your help.
Rich

No comments:

Post a Comment