[TUTORIAL] Historical Whole-Database Change Audit Querying

[Collin Lasley]

Howdy,

PowerSchool's Audit tables have come in handy several times, as well as some custom auditing systems we have in place. However, there are always times when someone asks me "Can you see who changed this record?" in a non-audited table. 99% of the time, I can only tell that the person asking was the last changer, since they already changed it back to how it should be.

If you really, really, really pester PowerSchool Support and get escalated to some of their higher-ups, you may have seen that they can seemingly audit all sorts of queries on your database, reaching far into the past. Ever wonder how they do that?

As an example: say somebody changed a kindergarten report card (a custom table in our district) to say that a particular student played poorly with others. The teacher noticed this and changed it back, but is now wondering who put the poor marks in the report card.

We can do this all without any PowerSchool downtime, flashing back the database, or restoring backups onto another instance as follows:

PART I: COLLECTING THE ARCHIVED LOG FILES

1. Determine when the data was changed. Try to get this range as narrow as you can, as this will speed up your search. It is important to note, however, that having a wide window will only make more work for the computer, not more work for you.
2. Log on to the PowerSchool database server, open a Command Prompt, and fire up RMAN. We will need to archive our current online log and then search through our backups to find the archive log files containing the changes we are looking for:
   1. ALTER SYSTEM ARCHIVE LOG CURRENT;
   2. ALTER SESSION SET NLS_DATE_FORMAT = 'DD-MON-YYYY HH24:MI:SS';
   3. LIST ARCHIVELOG FROM TIME '13-AUG-2023 00:00:00' UNTIL TIME '14-AUG-2023 10:00:00';
      List of Archived Log Copies for database with db_unique_name PSPRODDB
      ====================================================
      
      Key     Thrd Seq     S Low Time
      ------- ---- ------- - ---------
      751     1    54      A 12-AUG-23
              Name: C:\ORADATA\FAST_RECOVERY_AREA\PSPRODDB\ARCHIVELOG\ARCH_1_54_1143824925.DBF
      (truncated for brevity)
   4. If RMAN's output does not cover the entire window you are searching in, don't panic. Simply look through your backup files with the LIST BACKUP OF ARCHIVELOG command, create a temporary directory, and restore the needed archive logs there with a RUN block as follows:
      RMAN> RUN{
      2> SET ARCHIVELOG DESTINATION TO 'C:\ARCHLOG';
      3> RESTORE ARCHIVELOG FROM LOGSEQ=277 UNTIL LOGSEQ=277;
      4> }
3. Be sure to write down or copy/paste the paths to the log files that you will need.
   

PART II: SET UP LOGMINER

Now, EXIT from RMAN and fire up SQL*PLUS with SQLPLUS / AS SYSDBA

We now need to set up the Oracle LogMiner to analyze the archive logs:

• For the first log file in your list ONLY, run the following statement:
  • EXECUTE DBMS_LOGMNR.ADD_LOGFILE( LOGFILENAME => 'PATH_TO_THE_DBF_HERE', OPTIONS => DBMS_LOGMNR.NEW);
• For the ALL subsequent log files in your list, run the following statement:
  • EXECUTE DBMS_LOGMNR.ADD_LOGFILE( LOGFILENAME => 'PATH_TO_DBF_HERE', OPTIONS => DBMS_LOGMNR.ADDFILE);
• Now we can start LogMiner. One thing to note here is that LogMiner needs an Oracle Database Data Dictionary to process logs, but since the database that the logs came from is online (it's the PowerSchool database!), we can tell it to use that one:
  • EXECUTE DBMS_LOGMNR.START_LOGMNR( OPTIONS => DBMS_LOGMNR.DICT_FROM_ONLINE_CATALOG + DBMS_LOGMNR.PRINT_PRETTY_SQL);

PART III: QUERYING THE LOGS

Still with me? Good, we're almost done. Now, what we're about to do is search through a bunch of SQL UNDO and REDO statements, which are the logically equivalent and inverse statements to all of the changes in the database, both committed and uncommitted. We need some way to narrow down the query to what we're looking for. The entire list of parameters is available from Oracle here, but for this example, I'm going to just look for all of the changes to the U_KGREPORTCARD table. 

SELECT SQL_REDO FROM V$LOGMNR_CONTENTS WHERE SQL_REDO LIKE '%U_KGREPORTCARD%'

(Note: ****s below indicate redacted information below; the actual information appears in the results.)

update "PS"."U_KGREPORTCARDS"
  set
    "LAST_MODIFIED" = '8/15/2023',
    "MODIFIED_BY" = 'f369340',
    "WHOMODIFIED" = 'Lasley, Collin',
    "WHENMODIFIED" = '15-AUG-23 10.43.00.162000 AM'
  where
    ****

SQL_REDO
--------------------------------------------------------------------
update "PS"."U_KGREPORTCARDS"
  set
    "WHENMODIFIED" = '15-AUG-23 10.44.05.599000 AM'
  where
    ****

update "PS"."U_KGREPORTCARDS"
  set
    "SOCIAL_DEV_1" = 'NNNN'
  where
    ****

Well, there's good news and there's bad news. The good news is that we found the assailant. The bad news is that the assailant was me. If you need to undo the changes and don't know what they were before, simply re-run your query against the SQL_UNDO column: it will give you the exact SQL needed to undo the changes made by the offending statement.

Don't forget: before you close your SQL*PLUS Session, you will need to end your LogMiner session, otherwise you will consume unneeded resources on your server:

EXECUTE DBMS_LOGMNR.END_LOGMNR;

I hope someone finds this helpful, and that y'all can add it to your toolbox of catching baddies, assailants, and hooligans. The only other tip I have is that sometimes the "Who Modified" ID will seem to correspond to a number that you can't recognize. In this case, you simply need to match this number against the DCID column of the USERS table.

[Kyle Schneider]

Thanks for sharing this Collin! This is definitely useful for me.

I do want to point out that the tools Collin is using are only available for districts that self host their PowerSchool servers. If you rely on PowerSchool hosting, you’re not going to have access to RMAN or the ability to write directly to the Oracle database.

—
Kyle Schneider
GSD Educational Services
Desk: 907-917-4149
Cell: 802-281-8430
ky...@gsded.com

--
You received this message because you are subscribed to the Google Groups "AK PSUG" group.
To unsubscribe from this group and stop receiving emails from it, send an email to ak-psug+u...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/ak-psug/f31da41c-d712-40fd-a9f7-29ae17798678n%40googlegroups.com.

[Collin Lasley]

Oh, definitely. This would be far into the realm of "only do this on servers that you own;" I'm not sure what the ratio of self-hosted to PowerSchool-hosted servers is in Alaska. Here in Fairbanks we have far too many in-house integrations and custom systems to ever dream of moving it off-site, but I like it that way.

One other thing to mention: if you ever look at the log messages flashing by on PS Monitor, you've probably noticed that all web requests are listed as coming from the load balancer. When auditing records this way, PowerSchool gives the proper client IP address that made the request, at least in our setup (DB server, dedicated TaskMaster, dedicated report node, and three app nodes load-balanced with a dual-node F5 BIG-IP Traffic Manager). If your district manages its own WAN and you suspect that someone used stolen credentials, this would give a clue as to what security cameras to peek at to try to identify the person who changed the records, or whether the change took place on or off the district network.