Filter log

The filter log file shows all of the filters that were checked during an operation. If a filter was executed, the log also provides a list of the operations performed.

By default, the log file is named arfilter.log. 

This log is especially useful for checking the interaction of your filters and for verifying whether a filter is performing correctly.

The filter log format is similar to the SQL log format, but the information in the filter log is displayed over multiple lines. The log has the following characteristics:

  • Each line starts with a tag that identifies it as being a filter logging line (<FLTR> ).
  • A time stamp line is written for every operation that triggers filters.
  • A line indicates that processing has started and the operation is being performed.
  • A line provides details about the workflow object mode, indicating whether the object is Unmodified, Overlay object, or Custom. This information helps in easily troubleshooting filter related issues. Additionally, the log specifies the filter stack level and the corresponding filter number within the stack.
  • As each filter is checked, a message is written that includes the name of the filter, its escalation order, an indication of whether the filter passed the qualification, and any action taken with their results.
  • The last line contains a closing time stamp.

Phases 1, 2, and 3 of filter processing appear in the filter log. As AR System checks filters, all notify and run process actions are deferred to phase 3. Phase 3 begins when phases 1 and 2 are completed, and the database has been updated. In phase 3, all deferred filter actions are run. This information enables you to track the filters that are being checked, the filters that are running, and the actions that are being performed.

For more information about filter processing, see Filter-processing.

Related topics

Enabling-and-analyzing-logs

Analyzing-logs

Log-entry-format

The following example shows a portion of a filter log file:

<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000088685> <Queue: Fast      > <Client-RPC: 390620   > <USER: Remedy Application Service   > <Overlay-Group: 1         > /* Tue Feb 13 2024 00:22:48.0670 */ <Filter Level:0 Number Of Filters:3> Checking "AR System Configuration Component:SetPermissionForFresh" (500)" [Unmodified] 
<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000088685> <Queue: Fast      > <Client-RPC: 390620   > <USER: Remedy Application Service                   > <Overlay-Group: 1         > /* Tue Feb 13 2024 00:23:48.8020 */    End of filter processing (phase 1) -- Operation - GET on Configuration ARDBC - 000000000000037
<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000000017> <Queue: Fast      > <Client-RPC: 390620   > <USER: Demo                                         > <Overlay-Group: 1         > /* Tue Feb 13 2024 00:26:45.0960 */    Start filter processing (phase 1) -- Operation - SERVICE on NGC:Calendar - <NULL>
<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000000017> <Queue: Fast      > <Client-RPC: 390620   > <USER: Demo                                         > <Overlay-Group: 1         > /* Tue Feb 13 2024 00:26:45.1110 */ <Filter Level:0 Number Of Filters:0> Checking "NGC:CAL:GetBroadcastCount" (10)
<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000000017> <Queue: Fast      > <Client-RPC: 390620   > <USER: Demo                                         > <Overlay-Group: 1         >    --> Passed -- perform actions
<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000000017> <Queue: Fast      > <Client-RPC: 390620   > <USER: Demo                                         > <Overlay-Group: 1         >         0 : Call Guide "NGC:CAL:GetBroadcastCount_G"
<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000000017> <Queue: Fast      > <Client-RPC: 390620   > <USER: Demo                                         > <Overlay-Group: 1         > /* Tue Feb 13 2024 00:26:45.1420 */ <Filter Level:0 Number Of Filters:1> Checking "NGC:CAL:GetBroadcastLastViewDateTime" (0)
<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000000017> <Queue: Fast      > <Client-RPC: 390620   > <USER: Demo                                         > <Overlay-Group: 1         >    --> Passed -- perform actions
<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000000017> <Queue: Fast      > <Client-RPC: 390620   > <USER: Demo                                         > <Overlay-Group: 1         >         0 : Set Fields
<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000000017> <Queue: Fast      > <Client-RPC: 390620   > <USER: Demo                                         > <Overlay-Group: 1         >               z1D_BroadcastLastViewDateTime (302796500) =
<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000000017> <Queue: Fast      > <Client-RPC: 390620   > <USER: Demo                                         > <Overlay-Group: 1         > /* Tue Feb 13 2024 00:26:45.1420 */ <Filter Level:0 Number Of Filters:2> Checking "NGC:CAL:Broadcast Last Viewed Date Default" (0)
<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000000017> <Queue: Fast      > <Client-RPC: 390620   > <USER: Demo                                         > <Overlay-Group: 1         >    --> Passed -- perform actions
<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000000017> <Queue: Fast      > <Client-RPC: 390620   > <USER: Demo                                         > <Overlay-Group: 1         >         0 : Set Fields
<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000000017> <Queue: Fast      > <Client-RPC: 390620   > <USER: Demo                                         > <Overlay-Group: 1         >               z1D_BroadcastLastViewDateTime (302796500) = 12/6/1973 12:00:00 PM
<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000000017> <Queue: Fast      > <Client-RPC: 390620   > <USER: Demo                                         > <Overlay-Group: 1         > /* Tue Feb 13 2024 00:26:45.1580 */ <Filter Level:0 Number Of Filters:3> Checking "NGC:CAL:Broadcast_Get_Counts_Set112" (200)
<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000000017> <Queue: Fast      > <Client-RPC: 390620   > <USER: Demo                                         > <Overlay-Group: 1         >    --> Failed qualification -- perform else actions
<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000000017> <Queue: Fast      > <Client-RPC: 390620   > <USER: Demo                                         > <Overlay-Group: 1         > /* Tue Feb 13 2024 00:26:45.1580 */ <Filter Level:0 Number Of Filters:4> Checking "NGC:CAL:Broadcast Query For Count_Int" (800)
<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000000017> <Queue: Fast      > <Client-RPC: 390620   > <USER: Demo                                         > <Overlay-Group: 1         >    --> Passed -- perform actions
<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000000017> <Queue: Fast      > <Client-RPC: 390620   > <USER: Demo                                         > <Overlay-Group: 1         >         0 : Set Fields
<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000000017> <Queue: Fast      > <Client-RPC: 390620   > <USER: Demo                                         > <Overlay-Group: 1         >               z1D_BroadcastQual (301497300) = ('Broadcast Start Date' < "3/30/2015 12:26:45 AM") AND (('Broadcast Start Date' > "6/12/1973 12:00:00 PM") OR ('Last Modified Date' > "6/12/1973 12:00:00 PM")) AND (('Broadcast End Date' >= "3/30/2015 12:26:45 AM") OR ('Broadcast End Date' = $\NULL$))
<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000000017> <Queue: Fast      > <Client-RPC: 390620   > <USER: Demo                                         > <Overlay-Group: 1         >         1 : Set Fields
<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000000017> <Queue: Fast      > <Client-RPC: 390620   > <USER: Demo                                         > <Overlay-Group: 1         >               z1d_TempBrdMsg (302888800) =
<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000000017> <Queue: Fast      > <Client-RPC: 390620   > <USER: Demo                                         > <Overlay-Group: 1         >         2 : Set Fields
<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000000017> <Queue: Fast      > <Client-RPC: 390620   > <USER: Demo                                         > <Overlay-Group: 1         >               z1D_NewBroadcastCount (302889100) = 0
<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000000017> <Queue: Fast      > <Client-RPC: 390620   > <USER: Demo                                         > <Overlay-Group: 1         > /* Tue Feb 13 2024 00:26:45.1740 */ Call Guide "NGC:CAL:GetBroadcastCount_G" (return).
<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000000017> <Queue: Fast      > <Client-RPC: 390620   > <USER: Demo                                         > <Overlay-Group: 1         > /* Tue Feb 13 2024 00:26:45.1740 */    End of filter processing (phase 1) -- Operation - SERVICE on NGC:Calendar - <NULL>
<FLTR> <TrID: Ycc4EXa4Q_2u8fKTGcAcOg:0000064> <TID: 0000000359> <RPC ID: 0000088737> <Queue: Fast      > <Client-RPC: 390620   > <USER: Remedy Application Service                   > <Overlay-Group: 1         > /* Tue Feb 13 2024 00:31:50.2350 */    Start filter processing (phase 1) -- Operation - GET on Configuration ARDBC - 000000000000037

The filter in the example log performed two actions, a message and an alert. The alert was deferred to phase 3 filter actions. The log also shows the execution of another filter, Alert Events, which created the alert performed by the original filter. The execution of another filter will also occur on a Push Fields action.

When the log indicates a failed qualification, it does not mean that the filter malfunctioned. It means that the qualification was not met for this operation, so the else action runs, if present.

Tracking filter overlays

When the server executes a filter overlay, the filter log uses the real name of the overlay (<filterObjectName__o>). It also records the following message:

skipping overlaid object <filterObjectName>

When overlays are disabled on the server and the server executes an overlaid filter object, it records  the following message:

skipping overlay object <filterObjectName__o>

For information about overlay objects, see Customizing-applications-using-overlays-and-custom-objects.

 

Tip: For faster searching, add an asterisk to the end of your partial query. Example: cert*