Turn on suggestions
Auto-suggest helps you quickly narrow down your search results by suggesting possible matches as you type.
Showing results for
Turn on suggestions
Auto-suggest helps you quickly narrow down your search results by suggesting possible matches as you type.
Showing results for
Community Tip - Stay updated on what is happening on the PTC Community by subscribing to PTC Community Announcements. X
- Community
- PLM
- Windchill Discussions
- Re: Access Control Troubleshooting (verbose loggin...
Options
- Subscribe to RSS Feed
- Mark Topic as New
- Mark Topic as Read
- Float this Topic for Current User
- Bookmark
- Subscribe
- Mute
- Printer Friendly Page
Access Control Troubleshooting (verbose logging style)
Nov 06, 2014
04:21 PM
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Notify Moderator
Nov 06, 2014
04:21 PM
Access Control Troubleshooting (verbose logging style)
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!
Solved! Go to Solution.
Labels:
- Labels:
-
Other
ACCEPTED SOLUTION
Accepted Solutions
Dec 21, 2020
06:55 PM
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Notify Moderator
Dec 21, 2020
06:55 PM
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 2
Mar 17, 2015
06:08 AM
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Notify Moderator
Mar 17, 2015
06:08 AM
Many a thanks for such a helpful post. Keep them coming.
Dec 21, 2020
06:55 PM
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Notify Moderator
Dec 21, 2020
06:55 PM
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.
