How to Troubleshoot Live Smooth Streaming Issues? – Part 6 (IIS Logs and Others)

Friday, March 11, 2011

5. IIS Logs

Since smooth streaming client requests are all standard HTTP requests going through IIS pipeline, all these requests are being logged by IIS logs which are located in %systemdrive%\inetpub\logs\LogFiles\. An example of the log entries is shown below:

#Fields: date time s-ip cs-method cs-uri-stem cs-uri-query s-port cs-username c-ip cs(User-Agent) sc-status sc-substatus sc-win32-status sc-bytes time-taken

2010-10-26 18:05:41 2001:4898:0:fff:0:5efe:172.30.180.211 GET /test.isml QualityLevels(48000)&Fragments(audio=41795918) 80 - 2001:4898:0:fff:0:5efe:10.80.121.212 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.1;+WOW64;+Trident/5.0;+SLCC2;+.NET+CLR+2.0.50727;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30729;+Media+Center+PC+6.0;+InfoPath.3;+MS-RTC+LM+8) 200 0 0 11640 29

2010-10-26 18:05:41 2001:4898:0:fff:0:5efe:172.30.180.211 GET /test.isml QualityLevels(950000)&Fragments(video=60060000) 80 - 2001:4898:0:fff:0:5efe:10.80.121.212 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.1;+WOW64;+Trident/5.0;+SLCC2;+.NET+CLR+2.0.50727;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30729;+Media+Center+PC+6.0;+InfoPath.3;+MS-RTC+LM+8) 200 0 0 194803 334

The fields of the IIS log entries are configurable on IIS Manager UI in the “Logging” module. In general, it provides standard HTTP logging information including URIs, IPs, port, headers, status code, time taken, etc. There are many tools available for parsing and analyzing IIS logs. One tool that I often use is the “IIS Log Parser” that’s quite convenient and flexible for mining IIS log data. I have a few IIS Log Parser queries that I often use to gather statistic information for smooth streaming:

1. Status code count ordered by hit count
select sc-status, count(*) as hits from {LogFileName} group by sc-status order by hits desc

2. Client IP count ordered by hit count
select c-ip, count(*) as hits from {LogFileName} group by c-ip order by hits desc

3. Cient IPs that were hit for more than 10 times
select c-ip, count(*) as hits from {LogFileName} group by c-ip having hits>10 order by hits desc

4. Number of hits per hour during a time span
select quantize(to_timestamp(date,time), 3600) as hour, count(*) as hits from {LogFileName} where time>'22:00:00' and time<'23:59:59' group by hour

5. Get a section of the log based on a time span
select * from {LogFileName} where time>'22:00:00' and time<'23:59:59'

6. List the top 25 mostly hit URLs
select top 25 cs-uri-stem, cs-uri-query, sc-status, count(*) as hits from {LogFileName}group by cs-uri-stem, cs-uri-query, sc-status order by hits desc

7. List the top c-ip and status for a particular fragment request
select cs-uri-stem, cs-uri-query, sc-status, c-ip, count(*) as hits from {LogFileName}where cs-uri-stem='/test.isml' and cs-uri-query='QualityLevels(48000)&FragmentInfo(audio=652979953208)' group by cs-uri-stem, cs-uri-query, sc-status, c-ip order by hits desc

8. List the max/min/avg time-taken in the entire log
select max(time-taken) as max, min(time-taken) as min, avg(time-taken) as avg from {LogFileName}

9. List the top 10 verbs and Urls with the biggest time-taken
select top 10 cs-method, cs-uri-stem, time-taken from {LogFileName} order by time-taken desc

10. List the top 10 Urls for GET requests with the biggest time-taken
select top 10 cs-method, cs-uri-stem, time-taken from {LogFileName}where cs-method='GET' order by time-taken desc

11. Combining status with sub-status
select top 10 strcat(to_string(sc-status), strcat('.', to_string(sc-substatus))) as status, count(*) as hits from {LogFileName}group by status order by status asc

6. Fragment Response Code

When you look at the IIS logs for live smooth streaming, you might sometimes see some HTTP error codes. The most common error codes for live smooth streaming fragment response are 404 and 412. Here is how these error codes could happen:

HTTP 404 – This is the standard “File Not Found” error. For live smooth streaming, it could happen when the server didn’t receive a particular timestamp for certain bitrates. It’s usually caused by some data interruption for those bitrates. As we discussed in previous sections, in this case, server would still output this fragment timestamp to the manifest after some timeout. Smooth streaming client has a retry logic to automatically switch to other bitrates for this timestamp after it receives 404 error. So in most cases, a few 404 errors won’t have noticeable impact on the client’s playback experience.

HTTP 412 – This is a special error code for live smooth streaming. It means the client request is too far ahead of the encoder stream. In general due the nature of live streaming, client should not try to get ahead of the encoder (sorry but we can’t predict the future). The potential situations that could lead to this error are:

1. The client is indeed running too fast mostly because the client machine’s local clock is running faster than the encoder’s. This is possible but usually happens after a long time of playback. Smooth Streaming Client has internal logic to deal this with condition by adjusting its internal clock to better sync with the encoder’s clock. In most cases, it should have minimum impact on the playback experience.

2. The encoder stopped sending data to the server or some bitrates are terribly late. It could happen because of network issues, bandwidth issues or encoder’s internal issues. In this case, server would still send the client 412 response because the client is still running faster than the encoder stream. But in this case it’s not the fault of the client but rather due to the encoder data loss or delay. Smooth Streaming client will still do some retries trying to resume the streaming. But if all the bitrates are down for an extended period time, client would have no choice but to stop the playback and report error.

7. Others

Since IIS Live Smooth Streaming is running inside of the IIS web stack, there is quite some generic IIS information that could be useful. I’ll be just listing a few here and you can certainly find out more with your own investigation:

6.1 IIS Worker Process View

The “Worker Processes” module in IIS Manager displays all the current requests being handled by this worker process. So for live smooth streaming, you should see all your existing encoder connections here. This can help you confirm whether a particular encoder stream is still connected. From the “Time Elapsed” field, you can also tell when the connection was created and whether some connections were newly established compared to others.

6.2 HTTP.sys Log

IIS uses HTTP.sys for low level HTTP handling. HTTP.sys logs can be found under %windir%\System32\LogFiles\HTTPERR\. The log data here mostly contains similar information as IIS log but there are a few unique fields. For example, it shows the reason code for the ending of the TCP connection which can help you debug connection drop issues (e.g. was it caused by idle timeout or client reset?). Here is the link to the latest HTTP.sys log format (http://support.microsoft.com/kb/820729#2).

6.3 Failed Request Tracing Rules (aka “FREB”)

FREB is a very powerful tool to trace IIS internal request processing. It can help you identify issues that happened before Live Smooth Streaming module in the IIS pipeline (e.g. authentication failure). There are some good articles (link1 and link2) that walks through how to enable and use it.