S170 Policy trace says transaction permitted, but still redirected to block page

[keithsauer507]

I'm having an issue where sites are suddenly blocked when they shouldn't be.  When browsing to them we are redirected to our internal block page.  If I go into the S170 and run a policy trace, it says transaction permitted.

I am in the AD group for IT.  IT has an access policy that is high up in our list of access policies.  However according to the block page it is showing DefaultGroup-Authenticated, not Information Technology.  Policy trace seems to indicate I'm in the correct group, but not the web browsers.

What could be causing this?  I'll give you an example

Website block page:

Blocked Site:
www.slacker.com
Blocked Category:
Streaming Audio
User:
DOMAIN\sauerk@windows
User Group:
BLOCK_WEBCAT_12-DefaultGroup-Authenticated_Users-DefaultGroup-NONE-NONE-NONE

Policy Trace:

User Information
User Name: sauerk
Authentication Realm Group Membership: *removed for privacy*
Secure Group Tag Membership: None
User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/46.0.2490.71 Safari/537.36
URL Check
WBRS Score: 1.5
URL Category: Streaming Audio
Scanner "AVC" Verdict (Request): Unknown (Unknown)
Scanner "Webroot" Verdict (Request): Unknown
MIME-Type: text/html;charset=UTF-8
Scanner "AVC" Verdict (Response): Unknown (Unknown)
Policy Match
Cisco Data Security policy: None
Decryption policy: None
Routing policy: Global Routing Policy
Identification Profile: Authenticated_Users
Access policy: Information_Technology
Final Result
Request completed
Details: Transaction permitted
Trace session complete

[David Niemann]

What do the access logs on the proxy show? I've been told by several TAC engineers that the access logs are the definitive way to validate traffic.  The policy trace is not always "dependable" I believe I was told.

[keithsauer507]

Well I rebooted the appliance and now internet access appears as expected.  It came back up because I was able to ssh and go to the web interface of it.  Not sure if wccp really kicked in yet but things are opened up for me now.

On command line what is the best way to browse those logs?  

I ran grep

then 1 (for access logs)

regular expression I put my windows user name, then took the rest of the options as defaults as they were presented.  But then the screen scrolled so much information, I ended up killing it after 5 minutes of scrolling.

Now I tried a regular expression of my user name, a space and a website that was blocked.  It's just sitting there now after the last question, not presenting anything.  I may have to kill it again and try different regular expressions.

[keithsauer507]

Ok this time for regex I used the website address, in this test we used www.slacker.com (a streaming audio site).  This is a great test because regular users wouldn't have access to this site (those that fall under the last default group).

This time I told it to tail the output.  I then visited the website in google chrome and sure enough it started pulling in data to my putty window.

Yes the site is working now, so you think all I needed to do was a reboot?  I just rebooted it yesterday because it made the internet so slow we were receiving complaints.

1445429760.574 212 10.1.3.35 TCP_MISS/200 681 GET http://aksignal.slacker.com/crossdomain.xml "DOMAIN\sauerk@windows" DIRECT/aksignal.slacker.com application/xml DEFAULT_CASE_12-Information_Technology-Authenticated_Users-DefaultGroup-NONE-NONE-DefaultGroup <IW_aud,1.5,0,"-",0,0,0,1,"-",-,-,-,"-",0,0,"-","-",-,-,IW_aud,-,"Unknown","-","Unknown","Unknown","-","-",25.70,0,-,"Unknown","-",-,"-",-,-,"-","-"> -
1445429765.253 4621 10.1.3.35 TCP_MISS/200 3687620 GET http://aksignal.slacker.com/transcodings/v14c918b88fb/sny/2015/03/27/20150327170039661/A10301A0003318320Q/resources/mp3_128/A10301A0003318320Q_T-10366_SoundRecording_001-001.mp3?e=1445430958&rnd=1zLYP5QIty&cl=webplayer&os=1&h=56dd1eec97dc93466778cb79... "DOMAIN\sauerk@windows" DIRECT/aksignal.slacker.com audio/mpeg DEFAULT_CASE_12-Information_Technology-Authenticated_Users-DefaultGroup-NONE-NONE-DefaultGroup <IW_aud,1.5,0,"-",0,0,0,1,"-",-,-,-,"-",0,0,"-","-",-,-,IW_aud,-,"Unknown","-","MPEG","Media","-","-",6384.11,1,-,"Unknown","-",-,"-",-,-,"-","-"> -

[David Niemann]

Hard to say, you'd really have to go back into the logs and find the denies (if there are any) and see what the reason was.  Tailing the log is really most helpful when the actual problem is occurring.  After the fact you will have to search and I find searching on a syslog server with grep strings is most effective for me unless you have some kind of log correlator like Splunk.  You can also say yes to the last option for paginating the output and that should help you search the previous logs.  It will pause on every page of output.

[keithsauer507]

We are seeing another issue where a site was getting blocked called hightail.  Marketing needs this to receive a large graphic presentation from our partner firm.  So it showed as Block AVC and we went into the Application Visibility and Control and changed block to monitor for Hightail / Yousendit.

Now when we tail the logs, when the user access any regular site it appears they are correctly in the Marketing access group.  However when they (or I) try to access the hightail file share link that was given by the other firm, we are blocked and the log shows us in the OTHER-NONE-Authenticated_Users-DefaultGroup-NONE-NONE-DefaultGroup.  How can just visiting a different URL change the access category of the same user?  They tried logging off and on to make sure CDA picked up their access, which it is because I see the username to IP address mapping, and I see them in the correct group when they first log in it appears the pc checks in with our AV software and msn messenger by showing DEFAULT_CASE_12-Marketing-Authenticated_Users-DefaultGroup-None-NONE-DefaultGroup

[Handy Putra]

What is the version of the WSA(S170)? if the version is 8.5.x, WSA has defect in that platform where the policy will not hit correct policy that has authentication group membership in it and it will keep falls down to policy that does not have group membership in it (typically default policy).

The immediate workaround for this issue is to restart the prox process (do not really have to restart the whole appliance)

To restart prox process go to CLI -> diagnostic (hidden command) -> proxy -> kick

the defect is CSCuu49389 Race condition prevents authentication group matching, this defect normally occurs when the WSA receive update or configuration changes or SMA publish, etc that require the prox to restart and when it does the authentication process will restart as well and create race condition.

The defect has been verified fix in version 8.5.3 (still in ED release)

[techtone]

Thanks Handy, have the same issue on version 8.8.0-085. Proxy Kick worked.

[David Niemann]

the best thing to do is choose the Tail the logs option and then attempt the traffic again so you can watch it real time.  I prefer to send syslogs to a central syslog server as I have three WSAs being used with a WCCP redirect on an ASA.  I have all four devices logging into the same file on the syslog so I can see when the traffic hits the firewall and also which WSA it goes to.  To create a new syslog go under Log Subscriptions, Add Log Subscription, I named mine accesslogs_syslogs so as not to conflict with the default logs and point it to your syslog server.  I think you can also modify the default accesslogs, but I'm not sure if that results in you no longer having any local logs on the WSA so that's why I didn't do that.