Skip to main content
L
LoriSood23-Emerald I
23-Emerald I
November 6, 2014
Solved

Access Control Troubleshooting (verbose logging style)

  • November 6, 2014
  • 2 replies
  • 3034 views

Access control. Those two words alone can send the heartiest of men into a fit of tears when faced with trying to debug issues related to them. Tracking down why someone does or does not have access to something in Windchill can be downright tedious. Anytime you enable the wt.access.evaluation.* loggers you can pretty much expect to have to sift through a "War and Peace"-length log to get to the bottom of it.

Below is a mini-tutorial/demonstration on how to potentially troubleshoot access control issues where permission has been denied. Similar techniques can be used in other scenarios.

The following demonstrates an issue where a normal user needs to be able to modify team templates on the Team Administration page, but we don't know what permissions are needed for this action.


Start out by enabling the wt.access.evaluation.* logging (wt.access.evaluation.report, wt.access.evaluation.policyACL, wt.access.evaluation.securityLabels, and wt.access.evaluation.events set to ALL). This is done in the JMXConsole/SMJConsole (you could also do this by using the SetLogLevel action in a windchill shell) just before clicking anything in the Team Administration page when logged in as the regular user (lsood, in this case).

Once enabled one of the listed team templates is selected and immediately after the logging is disabled and logs analyzed.

In this particular case we are interested in anything that comes back saying that the access permission was false for Team-related objects (e.g. where “hasAccess is false” appears in the log and lsood is the user). The following is found in the log:

2014-04-22 19:50:15,320 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.report lsood -=> hasAccess: lsood, object = Team - Change Activity Team (wt.team.TeamTemplate:42967), permission = Modify

2014-04-22 19:50:15,331 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.report lsood -    type = WCTYPE|wt.team.TeamTemplate, domain = Site /System (wt.admin.AdministrativeDomain:8)

2014-04-22 19:50:15,332 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.report lsood -    checking for policy access ...

2014-04-22 19:50:15,334 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.policyACL lsood - => getPolicyAcl - IN: = wt.admin.AdministrativeDomain:8, wt.team.TeamTemplate

2014-04-22 19:50:15,378 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.policyACL lsood - <= getPolicyAcl - OUT - acl from cache: wt.admin.AdministrativeDomain:8, wt.team.TeamTemplate

2014-04-22 19:50:15,380 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.policyACL lsood -       + Participant: uid=bozo1,ou=people,cn=administrativeldap,cn=windchill_10.1,o=ptc (wt.org.WTUser:311123): [Full Control (All)]

2014-04-22 19:50:15,381 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.policyACL lsood -       + Participant: ALL: [Read]

2014-04-22 19:50:15,382 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.policyACL lsood -       + Participant: cn=lifecycleadministrators,ou=people,cn=administrativeldap,cn=windchill_10.1,o=ptc (wt.org.WTGroup:1424): [Read, Modify, Create, Delete]

2014-04-22 19:50:15,384 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.policyACL lsood -       + Participant: cn=administrators,ou=people,cn=administrativeldap,cn=windchill_10.1,o=ptc (wt.org.WTGroup:15): [Full Control (All)]

2014-04-22 19:50:15,385 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.policyACL lsood -       ! Participant: cn=view and print only,ou=people,cn=administrativeldap,cn=windchill_10.1,o=ptc (wt.org.WTGroup:24589): [Modify, Create, Delete, Administrative, Revise, New View Version, Change Permissions, Modify Content, Change Domain, Create By Move, Change Context, Set State, Modify Identity]

2014-04-22 19:50:15,388 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.report lsood - => AclEntrySet.getPermissionMasks: uid=lsood,ou=people,cn=enterpriseldap,cn=windchill_10.1,o=ptc, id = wt.org.WTUser:104696

2014-04-22 19:50:15,389 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.report lsood - <= AclEntrySet.getPermissionMasks: (from cache), grant = 1 [Read], absolute deny = 0 []

2014-04-22 19:50:15,390 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.report lsood -    object is ownable - check for owner rights

2014-04-22 19:50:15,391 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.report lsood -    checking for ad hoc access ...

2014-04-22 19:50:15,392 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.report lsood -<= hasAccess is false: lsood, object = Team - Change Activity Team (wt.team.TeamTemplate:42967), permission = Modify

Break down the logging:

  • The first bolded line indicates the beginning of the check (=> hasAccess) for a specific permission (Modify) and specifies the object type for which it is checking permissions (wt.team.TeamTemplate):


2014-04-22 19:50:15,320 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.report lsood -=> hasAccess: lsood, object = Team - Change Activity Team (wt.team.TeamTemplate:42967), permission = Modify


  • The next bolded text indicates the domain where it is checking for this permission. In this case it is the Site’s System domain.


2014-04-22 19:50:15,331 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.report lsood -    type = WCTYPE|wt.team.TeamTemplate, domain = Site /System (wt.admin.AdministrativeDomain:8)

It is searching here because the team template that I selected was created at the Site level. If I selected a team template created at the Org or Product/Library/Project level, then this domain would be the system domain for that context (i.e. Org’s System domain or Product/Library/Project’s System domain).

For example:


2014-04-22 20:03:12,703 DEBUG [RMI TCP Connection(13062)-10.198.108.33] wt.access.evaluation.report lsood -    type = WCTYPE|wt.team.TeamTemplate, domain = Site, Organization - Demo Organization, Demo Organization, Product - Lori Product, Demo Organization /System (wt.admin.AdministrativeDomain:322606)

The above line is essentially saying that it is checking the System domain under the Site > Demo Organization > Lori Product.

  • The middle section describes which groups/roles/users are being checked for access and what access those groups/roles/users have:

014-04-22 19:50:15,332 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.report lsood -    checking for policy access ...

2014-04-22 19:50:15,334 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.policyACL lsood - => getPolicyAcl - IN: = wt.admin.AdministrativeDomain:8, wt.team.TeamTemplate

2014-04-22 19:50:15,378 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.policyACL lsood - <= getPolicyAcl - OUT - acl from cache: wt.admin.AdministrativeDomain:8, wt.team.TeamTemplate

2014-04-22 19:50:15,380 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.policyACL lsood -       + Participant: uid=bozo1,ou=people,cn=administrativeldap,cn=windchill_10.1,o=ptc (wt.org.WTUser:311123): [Full Control (All)]

2014-04-22 19:50:15,381 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.policyACL lsood -       + Participant: ALL: [Read]

2014-04-22 19:50:15,382 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.policyACL lsood -       + Participant: cn=lifecycleadministrators,ou=people,cn=administrativeldap,cn=windchill_10.1,o=ptc (wt.org.WTGroup:1424): [Read, Modify, Create, Delete]

2014-04-22 19:50:15,384 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.policyACL lsood -       + Participant: cn=administrators,ou=people,cn=administrativeldap,cn=windchill_10.1,o=ptc (wt.org.WTGroup:15): [Full Control (All)]

2014-04-22 19:50:15,385 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.policyACL lsood -       ! Participant: cn=view and print only,ou=people,cn=administrativeldap,cn=windchill_10.1,o=ptc (wt.org.WTGroup:24589): [Modify, Create, Delete, Administrative, Revise, New View Version, Change Permissions, Modify Content, Change Domain, Create By Move, Change Context, Set State, Modify Identity]

The above says that the following permissions have been given for the following principals:

User: bozo1 has Full Control

Pseudo Role: ALL has Read

Group: Lifecycle Administrators has Read, Modify, Create and Delete

Group: Administrators has Full Control

Group View and Print Only has absolute deny on Modify, Create, Delete, Administrative, Revise, New View Version, Change Permissions, Modify Content, Change Domain, Create By Move, Change Context, Set State, Modify Identity

Note: a "+" before the "Participant:" text indicates permission(s) is granted, a "-" before the "Participant:" text indicates permission(s) is denied, and a "!" before the "Participant:" text indicates the permission(s) is absolute denied

  • The next section reconciles the user's permissions based on the association to groups/roles/users listed above and their permissions:

2014-04-22 19:50:15,388 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.report lsood - => AclEntrySet.getPermissionMasks: uid=lsood,ou=people,cn=enterpriseldap,cn=windchill_10.1,o=ptc, id = wt.org.WTUser:104696

2014-04-22 19:50:15,389 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.report lsood - <= AclEntrySet.getPermissionMasks: (from cache), grant = 1 [Read], absolute deny = 0 []

This means that lsood has been granted Read permission and no permissions have been absolutely denied. This indicates that the only group that lsood is associated with is  ALL  since that is the only one above that matches the same permission set.

  • The last bolded line in the above block indicates that the check is complete (<= hasAccess) and provides the result (lsood did not have the Modify permission):


2014-04-22 19:50:15,392 DEBUG [RMI TCP Connection(13034)-10.198.108.33] wt.access.evaluation.report lsood -<= hasAccess is false: lsood, object = Team - Change Activity Team (wt.team.TeamTemplate:42967), permission = Modify

Now that you know how to break down the access control logging output, hopefully troubleshooting such issues won't be quite as daunting. Happy access control hunting!

    Best answer by LoriSood

    There is another tip I'd like to mention regarding reviewing verbose access control logging. Access control is not checked synchronously so the output is not always synchronous either, and the permission checking output for different permissions can be mixed together because different threads can be checking permissions at the same time. It is important to pay attention to the thread that is outputting the permission. 

     

    Take the following example. Two permissions are being checked asynchronously (one highlighted in blue and the other in orange:

     

    2020-12-16 02:05:01,921 DEBUG [Thread-16] wt.access.evaluation.report - => hasAccess: Administrator, object = Table View Descriptor - com.ptc.windchill.wp.delivery.DeliveryRecordRB.193 (com.ptc.core.htmlcomp.tableview.TableViewDescriptor:2297578), permission = Read
    2020-12-16 02:05:01,922 DEBUG [Thread-16] wt.access.evaluation.report - type = WCTYPE|com.ptc.core.htmlcomp.tableview.TableViewDescriptor, domain = Site /System (wt.admin.AdministrativeDomain:8)
    2020-12-16 02:05:01,922 DEBUG [Thread-16] wt.access.evaluation.report - checking for policy access ...
    2020-12-16 02:05:01,922 DEBUG [Thread-16] wt.access.evaluation.policyACL - => getPolicyAcl - IN: = wt.admin.AdministrativeDomain:8, com.ptc.core.htmlcomp.tableview.TableViewDescriptor
    2020-12-16 02:05:01,949 DEBUG [QueryBuilder Type Pre-Loader] wt.access.evaluation.report - => hasAccess: Administrator, object = WTType Definition - wt.change2.WTChangeActivity2 (com.ptc.core.meta.type.mgmt.server.impl.WTTypeDefinition:21201909), permission = Read
    2020-12-16 02:05:01,950 DEBUG [QueryBuilder Type Pre-Loader] wt.access.evaluation.report - type = WCTYPE|com.ptc.core.meta.type.mgmt.server.impl.WTTypeDefinition, domain = Site /System (wt.admin.AdministrativeDomain:8)
    2020-12-16 02:05:01,950 DEBUG [QueryBuilder Type Pre-Loader] wt.access.evaluation.report - checking for policy access ...
    2020-12-16 02:05:01,950 DEBUG [QueryBuilder Type Pre-Loader] wt.access.evaluation.policyACL - => getPolicyAcl - IN: = wt.admin.AdministrativeDomain:8, com.ptc.core.meta.type.mgmt.server.impl.WTTypeDefinition
    2020-12-16 02:05:01,950 DEBUG [QueryBuilder Type Pre-Loader] wt.access.evaluation.policyACL - <= getPolicyAcl - OUT - acl from cache: wt.admin.AdministrativeDomain:8, com.ptc.core.meta.type.mgmt.server.impl.WTTypeDefinition
    2020-12-16 02:05:01,950 DEBUG [QueryBuilder Type Pre-Loader] wt.access.evaluation.policyACL - + Participant: cn=type administrators,ou=people,cn=administrativeldap,cn=windchill_11.2,o=PTC (wt.org.WTGroup:1134): [Full Control (All)]
    2020-12-16 02:05:01,950 DEBUG [QueryBuilder Type Pre-Loader] wt.access.evaluation.policyACL - + Participant: cn=administrators,ou=people,cn=administrativeldap,cn=windchill_11.2,o=PTC (wt.org.WTGroup:15): [Full Control (All)]
    2020-12-16 02:05:01,950 DEBUG [QueryBuilder Type Pre-Loader] wt.access.evaluation.policyACL - + Participant: All (Pseudo Role): [Read]
    2020-12-16 02:05:01,950 DEBUG [QueryBuilder Type Pre-Loader] wt.access.evaluation.report - => AclEntrySet.getPermissionMasks: uid=wcadmin,ou=people,cn=administrativeldap,cn=windchill_11.2,o=PTC, id = wt.org.WTUser:11
    2020-12-16 02:05:01,950 DEBUG [QueryBuilder Type Pre-Loader] wt.access.evaluation.report - <= AclEntrySet.getPermissionMasks: (from cache), grant = -1 [Full Control (All)], absolute deny = 0 []
    2020-12-16 02:05:01,950 DEBUG [QueryBuilder Type Pre-Loader] wt.access.evaluation.report - <= hasAccess is true: Administrator, object = WTType Definition - wt.change2.WTChangeActivity2 (com.ptc.core.meta.type.mgmt.server.impl.WTTypeDefinition:21201909), permission = Read
    2020-12-16 02:05:01,956 DEBUG [Thread-16] wt.access.evaluation.report - AclEntrySet.inflate
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.policyACL - <= getPolicyAcl - OUT - acl from cache: wt.admin.AdministrativeDomain:8, com.ptc.core.htmlcomp.tableview.TableViewDescriptor
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.policyACL - + Participant: cn=administrators,ou=people,cn=administrativeldap,cn=windchill_11.2,o=PTC (wt.org.WTGroup:15): [Full Control (All)]
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.policyACL - + Participant: All (Pseudo Role): [Read]
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.report - => AclEntrySet.getPermissionMasks: uid=wcadmin,ou=people,cn=administrativeldap,cn=windchill_11.2,o=PTC, id = wt.org.WTUser:11
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.report - group: Team Members (Library - Approval Library), id = wt.org.WTGroup:43371413
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.report - group: cn=windchill premium,ou=people,cn=administrativeldap,cn=windchill_11.2,o=PTC, id = wt.org.WTGroup:28338608
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.report - group: Library Manager (Library - Approval Library), id = wt.org.WTGroup:43371412
    2020-12-16 02:05:01,962 DEBUG [Thread-16] wt.access.evaluation.report - group: Library Manager (Library - Records), id = wt.org.WTGroup:25975460
    2020-12-16 02:05:02,050 DEBUG [Thread-16] wt.access.evaluation.report - <= AclEntrySet.getPermissionMasks: grant = -1 [Full Control (All)], absolute deny = 0 []
    2020-12-16 02:05:02,050 DEBUG [Thread-16] wt.access.evaluation.report - <= hasAccess is true: Administrator, object = Table View Descriptor - com.ptc.windchill.wp.delivery.DeliveryRecordRB.193 (com.ptc.core.htmlcomp.tableview.TableViewDescriptor:2297578), permission = Read

     

    In the above example, the output for the permission being checked by Thread-16 (Read permission for TableViewDescriptor) is interrupted by the output of a permission being checked by QueryBuilder Type Pre-Loader (Read permission for WTTypeDefinition). When analyzing access control logging, it is a good idea to use a good text editor, such as Notepad++ or TextPad, that allows for you to find all the lines that pertain to a particular thread (e.g., Thread-16) that you are interested in (e.g., the thread that is doing the check for the permission(s) you are interested in). Copy those lines into an empty file, and this will make checking the permissions checked by that thread a lot easier.

     

    Assuming we are interested in Thread-16, if we cut out the QueryBuilder Type Pre-Loader lines, the permission logging would look as we would expect:

     

    2020-12-16 02:05:01,921 DEBUG [Thread-16] wt.access.evaluation.report - => hasAccess: Administrator, object = Table View Descriptor - com.ptc.windchill.wp.delivery.DeliveryRecordRB.193 (com.ptc.core.htmlcomp.tableview.TableViewDescriptor:2297578), permission = Read
    2020-12-16 02:05:01,922 DEBUG [Thread-16] wt.access.evaluation.report - type = WCTYPE|com.ptc.core.htmlcomp.tableview.TableViewDescriptor, domain = Site /System (wt.admin.AdministrativeDomain:8)
    2020-12-16 02:05:01,922 DEBUG [Thread-16] wt.access.evaluation.report - checking for policy access ...
    2020-12-16 02:05:01,922 DEBUG [Thread-16] wt.access.evaluation.policyACL - => getPolicyAcl - IN: = wt.admin.AdministrativeDomain:8, com.ptc.core.htmlcomp.tableview.TableViewDescriptor
    2020-12-16 02:05:01,956 DEBUG [Thread-16] wt.access.evaluation.report - AclEntrySet.inflate
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.policyACL - <= getPolicyAcl - OUT - acl from cache: wt.admin.AdministrativeDomain:8, com.ptc.core.htmlcomp.tableview.TableViewDescriptor
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.policyACL - + Participant: cn=administrators,ou=people,cn=administrativeldap,cn=windchill_11.2,o=PTC (wt.org.WTGroup:15): [Full Control (All)]
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.policyACL - + Participant: All (Pseudo Role): [Read]
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.report - => AclEntrySet.getPermissionMasks: uid=wcadmin,ou=people,cn=administrativeldap,cn=windchill_11.2,o=PTC, id = wt.org.WTUser:11
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.report - group: Team Members (Library - Approval Library), id = wt.org.WTGroup:43371413
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.report - group: cn=windchill premium,ou=people,cn=administrativeldap,cn=windchill_11.2,o=PTC, id = wt.org.WTGroup:28338608
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.report - group: Library Manager (Library - Approval Library), id = wt.org.WTGroup:43371412
    2020-12-16 02:05:01,962 DEBUG [Thread-16] wt.access.evaluation.report - group: Library Manager (Library - Records), id = wt.org.WTGroup:25975460
    2020-12-16 02:05:02,050 DEBUG [Thread-16] wt.access.evaluation.report - <= AclEntrySet.getPermissionMasks: grant = -1 [Full Control (All)], absolute deny = 0 []
    2020-12-16 02:05:02,050 DEBUG [Thread-16] wt.access.evaluation.report - <= hasAccess is true: Administrator, object = Table View Descriptor - com.ptc.windchill.wp.delivery.DeliveryRecordRB.193 (com.ptc.core.htmlcomp.tableview.TableViewDescriptor:2297578), permission = Read

     

    Once the other thread is filtered out we can use the same technique described in the original post to analyze the permissions.

     

    A few more tips for making it easier to isolate what to focus on:

     

    1. If at all possible, enable the logging on a test server and/or perform testing when few users are logged into the system to minimize the amount of logging generated. Note that because these loggers are very verbose the logs can get rolled over so it is important to make sure that you check whether log rollover has happened when you get ready to analyze the logs (or send the logs into TS for analysis).

    2. Enable logging just prior to performing the action being tested and disable logging immediately after. Setting the logging using the wt.util.jmx.SetLogLevel command line utility or via Site > Utilities > Server Status > Monitoring Tools > Log Levels enables/disables the logging immediately. Setting the logging via log4jMethodServer.properties has a 2-3 minute delay.

    3. To more quickly find out what kinds of permissions are being checked, search for all instances of "hasAccess is".

     

    Note: Notepad++ and Textpad have the ability to search multiple files for all instances of a specified text.

     

    This can be filtered further by searching for all instances of "hasAccess is false" or "hasAccess is true" depending on whether you are interested in figuring out why a user is or is not being granted access to something. These lines give you a pretty good summary of the permissions being evaluated and will tell you the object type being checked, along with the user and the permission:

     

    2020-12-16 02:05:02,050 DEBUG [Thread-16] wt.access.evaluation.report - <= hasAccess is true: Administrator, object = Table View Descriptor - com.ptc.windchill.wp.delivery.DeliveryRecordRB.193 (com.ptc.core.htmlcomp.tableview.TableViewDescriptor:2297578), permission = Read

     

    If you find a particular user/object/permission combo that seems like it could be applicable to the situation, then  go to the line in the log that pertains to that permission check result and find the corresponding beginning of the check (e.g., 2020-12-16 02:05:01,921 DEBUG [Thread-16] wt.access.evaluation.report - => hasAccess: Administrator, object = Table View Descriptor - com.ptc.windchill.wp.delivery.DeliveryRecordRB.193 (com.ptc.core.htmlcomp.tableview.TableViewDescriptor:2297578), permission = Read ) earlier in the file so the permission analysis can be done.

     

     

    2 replies

    P
    Prabhash1-Visitor
    1-Visitor
    March 17, 2015

    Many a thanks for such a helpful post. Keep them coming.

    L
    LoriSood23-Emerald IAuthorAnswer
    23-Emerald I
    December 21, 2020

    There is another tip I'd like to mention regarding reviewing verbose access control logging. Access control is not checked synchronously so the output is not always synchronous either, and the permission checking output for different permissions can be mixed together because different threads can be checking permissions at the same time. It is important to pay attention to the thread that is outputting the permission. 

     

    Take the following example. Two permissions are being checked asynchronously (one highlighted in blue and the other in orange:

     

    2020-12-16 02:05:01,921 DEBUG [Thread-16] wt.access.evaluation.report - => hasAccess: Administrator, object = Table View Descriptor - com.ptc.windchill.wp.delivery.DeliveryRecordRB.193 (com.ptc.core.htmlcomp.tableview.TableViewDescriptor:2297578), permission = Read
    2020-12-16 02:05:01,922 DEBUG [Thread-16] wt.access.evaluation.report - type = WCTYPE|com.ptc.core.htmlcomp.tableview.TableViewDescriptor, domain = Site /System (wt.admin.AdministrativeDomain:8)
    2020-12-16 02:05:01,922 DEBUG [Thread-16] wt.access.evaluation.report - checking for policy access ...
    2020-12-16 02:05:01,922 DEBUG [Thread-16] wt.access.evaluation.policyACL - => getPolicyAcl - IN: = wt.admin.AdministrativeDomain:8, com.ptc.core.htmlcomp.tableview.TableViewDescriptor
    2020-12-16 02:05:01,949 DEBUG [QueryBuilder Type Pre-Loader] wt.access.evaluation.report - => hasAccess: Administrator, object = WTType Definition - wt.change2.WTChangeActivity2 (com.ptc.core.meta.type.mgmt.server.impl.WTTypeDefinition:21201909), permission = Read
    2020-12-16 02:05:01,950 DEBUG [QueryBuilder Type Pre-Loader] wt.access.evaluation.report - type = WCTYPE|com.ptc.core.meta.type.mgmt.server.impl.WTTypeDefinition, domain = Site /System (wt.admin.AdministrativeDomain:8)
    2020-12-16 02:05:01,950 DEBUG [QueryBuilder Type Pre-Loader] wt.access.evaluation.report - checking for policy access ...
    2020-12-16 02:05:01,950 DEBUG [QueryBuilder Type Pre-Loader] wt.access.evaluation.policyACL - => getPolicyAcl - IN: = wt.admin.AdministrativeDomain:8, com.ptc.core.meta.type.mgmt.server.impl.WTTypeDefinition
    2020-12-16 02:05:01,950 DEBUG [QueryBuilder Type Pre-Loader] wt.access.evaluation.policyACL - <= getPolicyAcl - OUT - acl from cache: wt.admin.AdministrativeDomain:8, com.ptc.core.meta.type.mgmt.server.impl.WTTypeDefinition
    2020-12-16 02:05:01,950 DEBUG [QueryBuilder Type Pre-Loader] wt.access.evaluation.policyACL - + Participant: cn=type administrators,ou=people,cn=administrativeldap,cn=windchill_11.2,o=PTC (wt.org.WTGroup:1134): [Full Control (All)]
    2020-12-16 02:05:01,950 DEBUG [QueryBuilder Type Pre-Loader] wt.access.evaluation.policyACL - + Participant: cn=administrators,ou=people,cn=administrativeldap,cn=windchill_11.2,o=PTC (wt.org.WTGroup:15): [Full Control (All)]
    2020-12-16 02:05:01,950 DEBUG [QueryBuilder Type Pre-Loader] wt.access.evaluation.policyACL - + Participant: All (Pseudo Role): [Read]
    2020-12-16 02:05:01,950 DEBUG [QueryBuilder Type Pre-Loader] wt.access.evaluation.report - => AclEntrySet.getPermissionMasks: uid=wcadmin,ou=people,cn=administrativeldap,cn=windchill_11.2,o=PTC, id = wt.org.WTUser:11
    2020-12-16 02:05:01,950 DEBUG [QueryBuilder Type Pre-Loader] wt.access.evaluation.report - <= AclEntrySet.getPermissionMasks: (from cache), grant = -1 [Full Control (All)], absolute deny = 0 []
    2020-12-16 02:05:01,950 DEBUG [QueryBuilder Type Pre-Loader] wt.access.evaluation.report - <= hasAccess is true: Administrator, object = WTType Definition - wt.change2.WTChangeActivity2 (com.ptc.core.meta.type.mgmt.server.impl.WTTypeDefinition:21201909), permission = Read
    2020-12-16 02:05:01,956 DEBUG [Thread-16] wt.access.evaluation.report - AclEntrySet.inflate
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.policyACL - <= getPolicyAcl - OUT - acl from cache: wt.admin.AdministrativeDomain:8, com.ptc.core.htmlcomp.tableview.TableViewDescriptor
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.policyACL - + Participant: cn=administrators,ou=people,cn=administrativeldap,cn=windchill_11.2,o=PTC (wt.org.WTGroup:15): [Full Control (All)]
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.policyACL - + Participant: All (Pseudo Role): [Read]
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.report - => AclEntrySet.getPermissionMasks: uid=wcadmin,ou=people,cn=administrativeldap,cn=windchill_11.2,o=PTC, id = wt.org.WTUser:11
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.report - group: Team Members (Library - Approval Library), id = wt.org.WTGroup:43371413
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.report - group: cn=windchill premium,ou=people,cn=administrativeldap,cn=windchill_11.2,o=PTC, id = wt.org.WTGroup:28338608
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.report - group: Library Manager (Library - Approval Library), id = wt.org.WTGroup:43371412
    2020-12-16 02:05:01,962 DEBUG [Thread-16] wt.access.evaluation.report - group: Library Manager (Library - Records), id = wt.org.WTGroup:25975460
    2020-12-16 02:05:02,050 DEBUG [Thread-16] wt.access.evaluation.report - <= AclEntrySet.getPermissionMasks: grant = -1 [Full Control (All)], absolute deny = 0 []
    2020-12-16 02:05:02,050 DEBUG [Thread-16] wt.access.evaluation.report - <= hasAccess is true: Administrator, object = Table View Descriptor - com.ptc.windchill.wp.delivery.DeliveryRecordRB.193 (com.ptc.core.htmlcomp.tableview.TableViewDescriptor:2297578), permission = Read

     

    In the above example, the output for the permission being checked by Thread-16 (Read permission for TableViewDescriptor) is interrupted by the output of a permission being checked by QueryBuilder Type Pre-Loader (Read permission for WTTypeDefinition). When analyzing access control logging, it is a good idea to use a good text editor, such as Notepad++ or TextPad, that allows for you to find all the lines that pertain to a particular thread (e.g., Thread-16) that you are interested in (e.g., the thread that is doing the check for the permission(s) you are interested in). Copy those lines into an empty file, and this will make checking the permissions checked by that thread a lot easier.

     

    Assuming we are interested in Thread-16, if we cut out the QueryBuilder Type Pre-Loader lines, the permission logging would look as we would expect:

     

    2020-12-16 02:05:01,921 DEBUG [Thread-16] wt.access.evaluation.report - => hasAccess: Administrator, object = Table View Descriptor - com.ptc.windchill.wp.delivery.DeliveryRecordRB.193 (com.ptc.core.htmlcomp.tableview.TableViewDescriptor:2297578), permission = Read
    2020-12-16 02:05:01,922 DEBUG [Thread-16] wt.access.evaluation.report - type = WCTYPE|com.ptc.core.htmlcomp.tableview.TableViewDescriptor, domain = Site /System (wt.admin.AdministrativeDomain:8)
    2020-12-16 02:05:01,922 DEBUG [Thread-16] wt.access.evaluation.report - checking for policy access ...
    2020-12-16 02:05:01,922 DEBUG [Thread-16] wt.access.evaluation.policyACL - => getPolicyAcl - IN: = wt.admin.AdministrativeDomain:8, com.ptc.core.htmlcomp.tableview.TableViewDescriptor
    2020-12-16 02:05:01,956 DEBUG [Thread-16] wt.access.evaluation.report - AclEntrySet.inflate
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.policyACL - <= getPolicyAcl - OUT - acl from cache: wt.admin.AdministrativeDomain:8, com.ptc.core.htmlcomp.tableview.TableViewDescriptor
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.policyACL - + Participant: cn=administrators,ou=people,cn=administrativeldap,cn=windchill_11.2,o=PTC (wt.org.WTGroup:15): [Full Control (All)]
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.policyACL - + Participant: All (Pseudo Role): [Read]
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.report - => AclEntrySet.getPermissionMasks: uid=wcadmin,ou=people,cn=administrativeldap,cn=windchill_11.2,o=PTC, id = wt.org.WTUser:11
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.report - group: Team Members (Library - Approval Library), id = wt.org.WTGroup:43371413
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.report - group: cn=windchill premium,ou=people,cn=administrativeldap,cn=windchill_11.2,o=PTC, id = wt.org.WTGroup:28338608
    2020-12-16 02:05:01,957 DEBUG [Thread-16] wt.access.evaluation.report - group: Library Manager (Library - Approval Library), id = wt.org.WTGroup:43371412
    2020-12-16 02:05:01,962 DEBUG [Thread-16] wt.access.evaluation.report - group: Library Manager (Library - Records), id = wt.org.WTGroup:25975460
    2020-12-16 02:05:02,050 DEBUG [Thread-16] wt.access.evaluation.report - <= AclEntrySet.getPermissionMasks: grant = -1 [Full Control (All)], absolute deny = 0 []
    2020-12-16 02:05:02,050 DEBUG [Thread-16] wt.access.evaluation.report - <= hasAccess is true: Administrator, object = Table View Descriptor - com.ptc.windchill.wp.delivery.DeliveryRecordRB.193 (com.ptc.core.htmlcomp.tableview.TableViewDescriptor:2297578), permission = Read

     

    Once the other thread is filtered out we can use the same technique described in the original post to analyze the permissions.

     

    A few more tips for making it easier to isolate what to focus on:

     

    1. If at all possible, enable the logging on a test server and/or perform testing when few users are logged into the system to minimize the amount of logging generated. Note that because these loggers are very verbose the logs can get rolled over so it is important to make sure that you check whether log rollover has happened when you get ready to analyze the logs (or send the logs into TS for analysis).

    2. Enable logging just prior to performing the action being tested and disable logging immediately after. Setting the logging using the wt.util.jmx.SetLogLevel command line utility or via Site > Utilities > Server Status > Monitoring Tools > Log Levels enables/disables the logging immediately. Setting the logging via log4jMethodServer.properties has a 2-3 minute delay.

    3. To more quickly find out what kinds of permissions are being checked, search for all instances of "hasAccess is".

     

    Note: Notepad++ and Textpad have the ability to search multiple files for all instances of a specified text.

     

    This can be filtered further by searching for all instances of "hasAccess is false" or "hasAccess is true" depending on whether you are interested in figuring out why a user is or is not being granted access to something. These lines give you a pretty good summary of the permissions being evaluated and will tell you the object type being checked, along with the user and the permission:

     

    2020-12-16 02:05:02,050 DEBUG [Thread-16] wt.access.evaluation.report - <= hasAccess is true: Administrator, object = Table View Descriptor - com.ptc.windchill.wp.delivery.DeliveryRecordRB.193 (com.ptc.core.htmlcomp.tableview.TableViewDescriptor:2297578), permission = Read

     

    If you find a particular user/object/permission combo that seems like it could be applicable to the situation, then  go to the line in the log that pertains to that permission check result and find the corresponding beginning of the check (e.g., 2020-12-16 02:05:01,921 DEBUG [Thread-16] wt.access.evaluation.report - => hasAccess: Administrator, object = Table View Descriptor - com.ptc.windchill.wp.delivery.DeliveryRecordRB.193 (com.ptc.core.htmlcomp.tableview.TableViewDescriptor:2297578), permission = Read ) earlier in the file so the permission analysis can be done.

     

     

      Terms & ConditionsAccessibility statement