Getting details from AI Files

ron

ron

Member
Linux 9.2, OE 11.7.20

We switch AI files every 12 minutes.

Last Friday a user deleted a record from a small reference table and I need to know who did it.

I copied all the AI files from Friday into a temp directory and used strings/grep to find which AI file contained a reference to the table involved, which was "bpaytrancode". That told me that just one file referenced that table:

$ strings 20241122090215^7701^20241122091414 | grep bpaytrancode
PUB.bpaytrancode

That told me that the change to table bpaytrancode occurred between 09:02 and 09:14.

I then used rfutil to produce a text extract of the AI file:

/progress/dlc/bin/rfutil /u2/testdb/test -C aimage scan verbose -a /tmp/20241122090215^7701^20241122091414 > /tmp/ai_unpacked

The ai_unpacked file contained a lot of details, but did not contain the string value "bpaytrancode" and therefore it was no help at all.

Is there any way to obtain further details?

Ron.
 
You might find this helpful:

Session: Inside The OpenEdge RDBMS: After-Image Log Records And Their Uses
Speaker: Gus Bjorklund
Excerpt: In this talk we will open the bonnet on the topic of After-Image Journaling and Recovery Log Records (aka “Notes”). We will describe what they are, what they do, and how to monitor them. But most importantly, we will show you some practical applications and uses of your newfound understanding of Notes.

 
ron said:
The ai_unpacked file contained a lot of details, but did not contain the string value "bpaytrancode" and therefore it was no help at all.
Click to expand...
The ai scan verbose output won't contain the table name. It contains a summary of the change notes. Let's look at a simple example (from 11.7.16).

I created a copy of the sports database. I created four AI areas and two new Type 2 areas:
Code: 
$ cat add.st
d "state":20,128;8 .
d "state_idx":21,128;8 .
a .
a .
a .
a .

Then I moved the state table into area 20 and its index into area 21, enabled AI, and switched to a new AI extent.

I ran the following code:
Code: 
find first state.
display recid( state ).  
delete state.

In this case, the recid of the deleted record (Alaska) was 1537. We'll come back to that later.

Then I ran rfutil ai scan verbose on the extent with the deletion notes. Here is the output.

Code: 
Trid: 0 code = RL_INMEM version = 3 (12528)
Trid: 0 dbkey = 0  update counter = 0 (12530)
Trid: 0 code = RL_LSTMOD version = 2 (12528)
Trid: 0 area = 6   dbkey = 32   update counter = 27 (12529)
Trid: 402 Wed Nov 27 14:27:20 2024. (2598)
Trid: 402 User Id: rob (12531)
Trid: 402 code = RL_TBGN version = 1 (12528)
Trid: 402 dbkey = 0  update counter = 0 (12530)
Trid: 402 code = RL_CXREM version = 2 (12528)
Trid: 402 area = 21   dbkey = 1536   update counter = 54 (12529)
Trid: 402 code = RL_RMDEL version = 2 (12528)
Trid: 402 area = 20   dbkey = 1536   update counter = 53 (12529)
Trid: 402 code = RL_RMCR version = 2 (12528)
Trid: 402 area = 20   dbkey = 1536   update counter = 54 (12529)
Trid: 402 Wed Nov 27 14:27:20 2024. (2598)
Trid: 402 code = RL_TEND version = 1 (12528)
Trid: 402 dbkey = 0  update counter = 0 (12530)

7 notes were processed. (1634)
0 in-flight transactions. (3785)
1 transactions were started. (1635)
1 transactions were completed. (11138)
At the end of the .ai file, 0 transactions were still active. (1636)

"Trid: <n>" is transaction ID. In this case, my changes happened in TrId 402.
The "code=RL_*" tokens show the type of AI note being processed.
When a record is deleted from a table, you will see AI notes like the following:
  • Transaction begin (RL_TBGN)
  • Delete index entry for the record (RL_CXREM)
    • There will be one of these notes for each index defined on the table. In this case, the state table has one index so there is one RL_CXREM note.
  • Delete the record (RL_RMDEL)
  • Transaction end (RL_TEND)
It could look more complicated than it does in this very simple example, e.g. if the table has delete triggers.

Here is what we see in the notes, step by step:

Trid: 402 Wed Nov 27 14:27:20 2024. (2598)
Trid: 402 User Id: rob (12531)
Trid: 402 code = RL_TBGN version = 1 (12528)
Trid: 402 dbkey = 0 update counter = 0 (12530)

Translation: User "rob" started a transaction with Trid 402 at time stamp Wed Nov 27 14:27:20 2024.

Trid: 402 code = RL_CXREM version = 2 (12528)
Trid: 402 area = 21 dbkey = 1536 update counter = 54 (12529)

This same transaction performed an index entry deletion (RM_CXREM) in the index block whose logical address is dbkey 1536 in storage area 21 (state_idx). This block write changed the block's update counter value to 54.

Trid: 402 code = RL_RMDEL version = 2 (12528)
Trid: 402 area = 20 dbkey = 1536 update counter = 53 (12529)

This same transaction deleted a record fragment (RM_RMDEL) in the record block whose logical address is dbkey 1536 in storage area 20 (state). This block write changed the block's update counter value to 53.

Trid: 402 code = RL_RMCR version = 2 (12528)
Trid: 402 area = 20 dbkey = 1536 update counter = 54 (12529)

This same transaction created a record fragment (RM_RMCR) in the record block whose logical address is dbkey 1536 in storage area 20 (state). This block write changed the block's update counter value to 54.

I think this note is for the creation of a rowid placeholder in the block, to prevent any other transaction from creating a new record fragment there with recid 1537, in case my transaction rolled back and the deleted fragment needed to be recreated.

Trid: 402 Wed Nov 27 14:27:20 2024. (2598)
Trid: 402 code = RL_TEND version = 1 (12528)
Trid: 402 dbkey = 0 update counter = 0 (12530)

Finally, this transaction with Trid 402 ended at time stamp Wed Nov 27 14:27:20 2024.

The takeaway here is that the single logical operation of deleting one record is made up of several parts (notes). Some of these note types are for housekeeping like RL_TBGN and RL_TEND; transaction begin and end. Some of these note types (RL_CXREM, RL_RMDEL, RL_RMCR) describe physical operations on database blocks (not on logical entities like tables or indexes), so they don't reference a table or index number or name. In this case, my objects were in Type 2 areas and so each block in a data area belongs to one and only one storage object, but that wouldn't be the case in a Type 1 area.

In my example, I knew the recid of the deleted record in advance, because I displayed it before deleting the record. In your case, you would need an earlier copy of the database that still contains the record, so you could find the record in that copy and then display the recid. You need this because the RL_RMDEL note provides the area number and block address (dbkey). You can derive the dbkey of the record block if you know the recid of a record fragment in that block and the RPB (record per block) of the storage area. In my case:

recid of deleted record = 1537
RPB of area 20 = 128
dbkey = recid - (recid modulo RPB) = 1537 - (1537 modulo 128) = 1537 - 1 = 1536.

Once you have the area number and dbkey, you can grep through your ai scan verbose output for a line with "code = RL_RMDEL" followed by a line with "area = <your area number>" and "dbkey = <your dbkey>". From those lines, you will have the Trid of the transaction that deleted the record. Then by further grepping for "Trid: <your trid>" and "RL_TBGN" and "RL_TEND", you will know the window of time in which the transaction happened and the user name (though unfortunately not the user number) of the user who performed the action.

If desired, you can compare that info against your database log for more info like when they logged in and out that day, which terminal or remote IP address they used, etc. And you can look further through the ai scan verbose logs to see any other changes they may have made in other transactions. I hope this helps.
 
> a user deleted a record from a small reference table and I need to know who did it.

The table and its indexes are resided in the public areas, aren't them?

How many blocks are used by the bpaytrancode table?
How many blocks are used by the indexes of bpaytrancode table?
If the numbers are rather small then you can grep all of their dbkeys (together with the area numbers) in ai scans.
If the numbers are rather large then you can try to look only for the object blocks of the table and its indexes but it's not guaranteed the object blocks were updated when the record was deleted.
When you will find all transactions that updated the bpaytrancode table you can try to find which transaction has deleted a record.

> The ai scan verbose output won't contain the table name.

True. Nevertheless AI scans do allow to find out the names of the objects that own dbkeys if ai scans are large enough. Unfortunately we need a tool to do that but I have not seen any interest from Progress community in such a tool.

1. The number of blocks owned by table and its indexes:
proutil db -C viewB2 | grep PUB.bpaytranscode

2. Dbkeys used by table:
for each bpaytranscode no-lock
break by dbkey(bpaytranscode):
if first-of(dbkey(bpaytranscode)) then
put dbkey(bpaytranscode) skip.
end.

3. Dbkeys used by table's indexes (the index delete chain is not included):
proutil db -C idxblockreport bpaytranscode.$INDEXNAME

4. Dbkeys of the object blocks:
_StorageObject._Object-block

If any of these dbkeys is mentioned in ai scan then it was a transaction that updated the bpaytranscode table.
 
Last edited:
Thank you very much for the replies. One thing that surprised me was that the table name "PUB.bpaytranscode" exists as a plain-text string in the AI file, but that name is not shown in the AI scan.

I will study your replies during the next few days and see if I can extract further details.
Ron.
 
For what it's worth, the text "state", the name of the table from which I deleted the record, was not present in my ai scan verbose output. I wouldn't focus on the table name.
 
You must log in or register to reply here.
Back
Top