Database Demo:
Logging, Recovery, Auditing, Replication

The following document contains screen snippets from a live demo showing the Eloquence features forward-logging and recovery, database auditing and server replication. The screen snippets have been taken on Linux, but the same demo could also be performed on HP-UX with only minor changes (e.g. in path names like /etc/init.d versus /sbin/init.d).


  1. Overview of the ToyDB database server
  2. Forward Logging and Recovery
  3. Database Auditing
  4. Database Server Replication
  5. Documentation References

Overview of the ToyDB database server

In this section we will just have a brief look at the sample database
server that is used during this demonstration. It is a small Eloquence B.08.10
database server with a single database named TOYDB. It is installed in the home
directory of a demo user and uses dedicated TCP port numbers that differ from the
default Eloquence port numbers. This way we can run the demo without interfering
with an existing Eloquence installation.
Here is a brief look at our config and volume files...
demo@linux:~> /etc/init.d/eloq81 info demo
 eloqdb instance id = demo
  configuration file = /home/demo/eloqdb.cfg
  service = 3000
  args =
  run prefix =
  automatic start = 0
  user = demo
  eloqdb = /opt/eloquence/8.1/bin/eloqdb

demo@linux:~> /etc/init.d/eloq81 status demo
eloqdb[demo] process is active (pid 7914)                            running

demo@linux:~> ll
total 108
drwxr-xr-x 2 demo users  4096 2010-07-21 15:13 bin
 ...
-rw-r--r-- 1 demo users 21465 2010-07-23 08:58 eloqdb.cfg
-r--r--r-- 1 demo users 21691 2010-07-23 08:43 eloqdb.cfg,v
-rw-r--r-- 1 demo users  4142 2010-07-23 09:13 eloqdb.log
drwxr-xr-x 2 demo users  4096 2010-07-23 08:55 log
 ...
drwxr-xr-x 4 demo users  4096 2010-07-23 09:12 tmp
 ...
drwxr-xr-x 2 demo users  4096 2010-07-23 08:58 vol

demo@linux:~> ll vol
total 7680
-rw------- 1 demo users 2621440 2010-07-23 09:15 db-01.vol
-rw------- 1 demo users 2621440 2010-07-23 09:09 db-02.vol
-rw------- 1 demo users 2621440 2010-07-23 09:15 log-1.vol

demo@linux:~> dbvoldump -c eloqdb.cfg

ELOQUENCE DBVOLDUMP (C) Copyright 2010 Marxmeier Software AG (B.08.10)

ID  Type Path
1   DATA /home/demo/vol/db-01.vol
2   DATA /home/demo/vol/db-02.vol
3   LOG  /home/demo/vol/log-1.vol

ID  Type  Cur.Sz  Ext.Sz  Max.Sz    Free    Used
1   DATA     2.5     1.0     0.0     0.8     1.7
2   DATA     2.5     1.0     0.0     2.4     0.1
3   LOG      2.5     1.0     0.0     2.5     0.0


We use rcs for tracking config changes, so we can show
where we customized the supplied template file...
demo@linux:~> rcsdiff -r1.1 eloqdb.cfg
===================================================================
RCS file: eloqdb.cfg,v
retrieving revision 1.1
diff -r1.1 eloqdb.cfg
29c29
< #Title =
---
> Title = demo server
41,42c41,42
< #Service = eloqdb
< #ServiceHttp =
---
> Service = 3000
> ServiceHttp = 3080
56c56
< #panic = restart
---
> panic = exit
66,67c66,67
< UID = eloqdb
< GID = eloqdb
---
> UID = demo
> GID = users
114c114
< #LogFile = syslog
---
> LogFile = /home/demo/eloqdb.log
172c172
< #LogFlags = *0
---
> LogFlags = *1E2
531,533c531,533
<
< # List of data base volumes. Initially empty.
< # This is usually filled in by dbvolcreate and dbvolextend utilities
---
> Root = /home/demo/vol/db-01.vol
> Vol02 = /home/demo/vol/db-02.vol
> Log03 = /home/demo/vol/log-1.vol


Notice that we have ServiceHttp enabled so that we can monitor the
database server status with a web browser. We also have configured the
server to use a dedicated logfile instead of syslog, so we do not have
our database related messages mixed with other syslog content. We also
use LogFlags beyond the *0 default; this way our logfile contains info
on client connections including extended audit info like user name and
program name.
In the live demo we ran a session that opens the database
and holds a lock, so we could view examples of the status web pages. The
resulting web pages are not included here, but you can view similar pages
on the web at the following web site location:

http://eloquence.marxmeier.com/support/B0710/doc/http-status/index.html


The database server is running under our demo user and we have
configured the START_STOP_AS_ROOT setting in /etc/sysconfig/eloquence81
so that we do not need root access for controlling our own server.
We are using a non-default port number for the server, so we need
to remember setting the EQ_DBSERVER environment variable in our sessions:
demo@linux:~> env | grep EQ
EQ_DBSERVER=:3000

Here some info on the small TOYDB database that we use...
demo@linux:~> dbdumpcat -t 31

ELOQUENCE DBDUMPCAT (C) Copyright 2010 Marxmeier Software AG (B.08.10)

-------------------------------------------
#31 sysdb (1 entries)
-------------------------------------------
|dbid|name                |flags   |nodeid|
-------------------------------------------
|11  |TOYDB               |04000000|100   |
-------------------------------------------

demo@linux:~> dbinfo toydb

ELOQUENCE DBINFO (C) Copyright 2010 Marxmeier Software AG (B.08.10)

Processing database: toydb

SET NAME               RECLEN CAPACITY ENTRIES
---------------- --- - ------ -------- --------
PRODUCTS         001 M     30     1456       10
CUSTOMERS        002 M    260      229        8
ORDER-MASTER     003 A      8     1456       15
INVOICES         004 D     40     1149        1
ORDERS           005 D     18     1771       15
ORDER-DETAILS    006 D     20     1771       15

demo@linux:~> dbtables -s toydb

ELOQUENCE DBTABLES (C) Copyright 2010 Marxmeier Software AG (B.08.10)

 . . .
                         D A T A   S E T   F I E L D S

Data Set Name    Set  Item Name        Item  Item  Recd   Item  Item  Item
                 Num                   Num   Type  Ofs    Cnt   Len   Role

PRODUCTS           1  PRODUCT-NO         15  X6        0     1     6  Srch
                      PRODUCT-NAME       14  X16       6     1    16
                      PRICE              12  P4       22     1     4
                      PRODUCT-LINE       13  X2       26     1     2
                      QUANTITY           16  I2       28     1     2
 . . .


Forward Logging and Recovery
In this section, we enable forward logging for our database server,
take an online backup, perform a couple of transactions against our server
and then simulate a user error that damages our data. We then perform the
recovery steps by restoring the backup and rolling forward up to a point in
time that is shortly before our simulated disaster.
Here are the changes for enabling forward logging...
demo@linux:~> rcsdiff eloqdb.cfg
===================================================================
RCS file: eloqdb.cfg,v
retrieving revision 1.2
diff -r1.2 eloqdb.cfg
479c479
< #FwLog = /data/fwlog/fw-%N.log
---
> FwLog = /home/demo/log/fw-%N.log
514c514
< #EnableAudit = 0
---
> EnableAudit = 1


Notice that we also enable the auditing feature with above config changes;
this is not really required by this specific part of the demo, but it will be
helpful in the next section as it will save us another server restart.
We need to restart the database server to activate the config changes...
demo@linux:~> /etc/init.d/eloq81 restart demo
Stopping eloqdb[demo] daemon                                         done
Starting eloqdb[demo] daemon                                         done

demo@linux:~> tail -20 eloqdb.log
Fri 23 09:20:22 ( 7914) T1: [4] Exiting thread kernel ...
Fri 23 09:20:22 ( 7914) D1: Eloquence database server shutting down
Fri 23 09:20:22 ( 7914) D0: Eloquence data base server terminated

** Fri Jul 23 09:20:23 2010   Flags = [*1E2]

Fri 23 09:20:23 ( 8121) D1: Eloquence data base server initializing
Fri 23 09:20:23 ( 8122) D0: Server patch level B0810
Fri 23 09:20:23 ( 8122) D0: Server supports data encryption
Fri 23 09:20:23 ( 8122) D1: [0] /home/demo/vol/db-01.vol
Fri 23 09:20:23 ( 8122) D1: [1] /home/demo/vol/db-02.vol
Fri 23 09:20:23 ( 8122) D1: [2] /home/demo/vol/log-1.vol
Fri 23 09:20:23 ( 8122) C1: Setting up buffer cache: 8192 buffers
Fri 23 09:20:23 ( 8122) L1: volume recovery: state of committed transactions is OK
Fri 23 09:20:23 ( 8122) L1: volume recovery: state of volume is OK
Fri 23 09:20:23 ( 8122) L0: created new forward-log segment (/home/demo/log/fw-0-1.log)
Fri 23 09:20:23 ( 8122) T1: Number of CPU cores in processor set is 1
Fri 23 09:20:23 ( 8122) D1: Communication buffer size = 1327104
Fri 23 09:20:23 ( 8122) D1: Communication buffer shmid = 327685
Fri 23 09:20:23 ( 8122) D0: Eloquence database server active


He is the first forward log that is being written to...
demo@linux:~> ll log
total 4
-rw------- 1 demo users 118 2010-07-23 09:20 fw-0-1.log

demo@linux:~> dbctl forwardlog status
Forward-logging is enabled.
Forward-log is '/home/demo/log/fw-0-1.log'.


Now we perform an online backup, which is the base for recovery...
Notice that backup mode switches to a new forward-log generation
number, which is also recorded inside the volume files. This way the
server is able to identify the matching logfiles in case of recovery.

demo@linux:~> dbctl -u dba backup start
On-line backup mode has been started.

demo@linux:~> dbctl forwardlog status
Forward-logging is enabled.
Forward-log is '/home/demo/log/fw-1-1.log'.

demo@linux:~> ll log
total 8
-rw------- 1 demo users 127 2010-07-23 09:24 fw-0-1.log
-rw------- 1 demo users 118 2010-07-23 09:24 fw-1-1.log

demo@linux:~> tar cvzf tmp/backup-1.tar.gz eloqdb.cfg vol/db*.vol
eloqdb.cfg
vol/db-01.vol
vol/db-02.vol


Notice that we only backup the server config and the data volume
files, which are stable and consistent during online backup mode.
In real life we would probably also backup the forward-logs that
were created since our last backup, excluding the currently active log.
For bigger systems we might even want to backup or copy the finished
forward logs in regular intervals to limit the window of vulnerability.

Notice that stopping online backup mode does not switch logs...
demo@linux:~> dbctl -u dba backup stop
On-line backup mode has been stopped.

demo@linux:~> ll log
total 8
-rw------- 1 demo users 127 2010-07-23 09:24 fw-0-1.log
-rw------- 1 demo users 118 2010-07-23 09:24 fw-1-1.log


Now we perform some database transactions. Out of a habit,
I am using the query3k utility...
demo@linux:~> query3k
B.08.10.00 Eloquence QUERY3K  FRI, JUL 23, 2010,  9:26 AM
Copyright 2004-2010 Marxmeier Software AG
Copyright 2004 Hewlett-Packard Development Company, L.P.

>base=toydb
PASSWORD = >>
MODE = >>1
>add products
PRODUCT-NO      =>>4711
PRODUCT-NAME    =>>eau de cologne
PRICE           =>>123
PRODUCT-LINE    =>>xy
QUANTITY        =>>456

PRODUCT-NO      =>>//
>exit


We also create a test database TOYDB.TEST using export and import...
demo@linux:~> prschema toydb >tmp/toydb.schema

ELOQUENCE PRSCHEMA (C) Copyright 2010 Marxmeier Software AG (B.08.10)

demo@linux:~> dbexport -s tmp/toydb.export toydb

ELOQUENCE DBEXPORT (C) Copyright 2010 Marxmeier Software AG (B.08.10)

demo@linux:~> schema -b toydb.test tmp/toydb.schema

ELOQUENCE SCHEMA (C) Copyright 2010 Marxmeier Software AG (B.08.10)
PAGE  1    TOYDB.TEST           ELOQUENCE SCHEMA PROCESSOR B.08.10

BEGIN DATA BASE TOYDB;
*** (WARNING #21) Database name already specified (ignored) in line 4

Number of warnings      : 1
Item name count         : 23
Index item name count   : 0
Data set count          : 6
Collating sequence count: 0

*** Database catalog created

demo@linux:~> dbcreate toydb.test

ELOQUENCE DBCREATE (C) Copyright 2010 Marxmeier Software AG (B.08.10)

demo@linux:~> dbimport -s tmp/toydb.export toydb.test

ELOQUENCE DBIMPORT (C) Copyright 2010 Marxmeier Software AG (B.08.10)

importing from database TOYDB


So we now have TOYDB and TOYDB.TEST ...
demo@linux:~> dbinfo toydb

ELOQUENCE DBINFO (C) Copyright 2010 Marxmeier Software AG (B.08.10)

Processing database: toydb

SET NAME               RECLEN CAPACITY ENTRIES
---------------- --- - ------ -------- --------
PRODUCTS         001 M     30     1456       11
CUSTOMERS        002 M    260      229        8
ORDER-MASTER     003 A      8     1456       15
INVOICES         004 D     40     1149        1
ORDERS           005 D     18     1771       15
ORDER-DETAILS    006 D     20     1771       15

demo@linux:~> dbinfo toydb.test

ELOQUENCE DBINFO (C) Copyright 2010 Marxmeier Software AG (B.08.10)

Processing database: toydb.test

SET NAME               RECLEN CAPACITY ENTRIES
---------------- --- - ------ -------- --------
PRODUCTS         001 M     30     1456       11
CUSTOMERS        002 M    260      229        8
ORDER-MASTER     003 A      8     1456       15
INVOICES         004 D     40     1149        1
ORDERS           005 D     18     1771       15
ORDER-DETAILS    006 D     20     1771       15


Another transaction to our TOYDB database...
demo@linux:~> query3k
B.08.10.00 Eloquence QUERY3K  FRI, JUL 23, 2010,  9:28 AM
Copyright 2004-2010 Marxmeier Software AG
Copyright 2004 Hewlett-Packard Development Company, L.P.

>base=toydb
PASSWORD = >>
MODE = >>1
>find products.product-no=4711
1  ENTRIES QUALIFIED
>replace price="0"; end
>list products

PRODUC  PRODUCT-NAME         PRICE  PR  QUANTI

A00003  POKER DICE SET         125  10     500
A00008  POSTER PAINTS           95  30    1250
A00009  COLOURING BOOK          65  30    1000
A00001  PACK OF CARDS           75  10    1500
A00010  ERASER GIFT SET        185  30    1500
A00002  LUDO SET              1250  10     750
A00005  15" PINK RABBIT       1745  20     200
A00007  SET OF CRAYONS         175  30     500
A00004  12" TEDDY BEAR        1525  20     250
A00006  SET OF PANDAS         2500  20     150
4711    eau de cologne           0  xy     456

>exit


And finally we erase our test database...
demo@linux:~> dberase toydb

ELOQUENCE DBERASE (C) Copyright 2010 Marxmeier Software AG (B.08.10)


Ooops! Faux pas! By pressing Return too early,
we erased the wrong database. Ouch! ;-)
demo@linux:~> dbinfo toydb   # notice the missing .TEST

ELOQUENCE DBINFO (C) Copyright 2010 Marxmeier Software AG (B.08.10)

Processing database: toydb

SET NAME               RECLEN CAPACITY ENTRIES
---------------- --- - ------ -------- --------
PRODUCTS         001 M     30        0        0
CUSTOMERS        002 M    260        0        0
ORDER-MASTER     003 A      8        0        0
INVOICES         004 D     40        0        0
ORDERS           005 D     18        0        0
ORDER-DETAILS    006 D     20        0        0



To recover from this (intentional) "disaster" we will first
restore the most recent backup and then apply the logged transactions up to
a point short before the (pretended) user error.
For finding the "right" point in time, it pays off that we are running
our database server with LogFlags *1E2 instead of the default *0 settings.
The extended audit events of log level E1 and E2 are quite helpful in finding
out which user ran which program against the database recently...
demo@linux:~> grep -e E1: -e E2: eloqdb.log | tail -20
Fri 23 09:27:46 ( 8122) E2: [9] Audit: uid{1000}pid{8492}pname{dbcreate toydb.test}
Fri 23 09:27:46 ( 8122) E1: [9] Login: "dba" from 127.0.0.1:57763/demo
Fri 23 09:27:57 ( 8122) E2: [9] Audit: protocol{a}os{Linux}ip{127.0.0.1}user{demo}
Fri 23 09:27:57 ( 8122) E2: [9] Audit: uid{1000}pid{8494}pname{dbimport -s tmp/toydb.export toydb.test}
Fri 23 09:27:57 ( 8122) E1: [9] Login: "public" from 127.0.0.1:57764/demo
Fri 23 09:28:30 ( 8122) E2: [9] Audit: protocol{a}os{Linux}ip{127.0.0.1}user{demo}
Fri 23 09:28:30 ( 8122) E2: [9] Audit: uid{1000}pid{8496}pname{dbinfo toydb}
Fri 23 09:28:30 ( 8122) E1: [9] Login: "public" from 127.0.0.1:57765/demo
Fri 23 09:28:36 ( 8122) E2: [9] Audit: protocol{a}os{Linux}ip{127.0.0.1}user{demo}
Fri 23 09:28:36 ( 8122) E2: [9] Audit: uid{1000}pid{8498}pname{dbinfo toydb.test}
Fri 23 09:28:36 ( 8122) E1: [9] Login: "public" from 127.0.0.1:57766/demo
Fri 23 09:29:05 ( 8122) E2: [9] Audit: protocol{a}os{Linux}ip{127.0.0.1}user{demo}
Fri 23 09:29:05 ( 8122) E2: [9] Audit: uid{1000}pid{8500}pname{query3k}
Fri 23 09:29:05 ( 8122) E1: [9] Login: "public" from 127.0.0.1:57767/demo
Fri 23 09:29:48 ( 8122) E2: [9] Audit: protocol{a}os{Linux}ip{127.0.0.1}user{demo}
Fri 23 09:29:48 ( 8122) E2: [9] Audit: uid{1000}pid{8502}pname{dberase toydb}
Fri 23 09:29:48 ( 8122) E1: [9] Login: "dba" from 127.0.0.1:57768/demo
Fri 23 09:29:56 ( 8122) E2: [9] Audit: protocol{a}os{Linux}ip{127.0.0.1}user{demo}
Fri 23 09:29:56 ( 8122) E2: [9] Audit: uid{1000}pid{8504}pname{dbinfo toydb}
Fri 23 09:29:56 ( 8122) E1: [9] Login: "public" from 127.0.0.1:57769/demo


So our recovery should better not re-apply the dberase step.
For recovering, we shutdown the damaged database server, restore the
data volumes from our most recent backup, create a fresh and matching log
volume (optional in case of a clean shutdown), and finally use dbrecover
to re-apply the logged transactions...
demo@linux:~> /etc/init.d/eloq81 stop demo
Stopping eloqdb[demo] daemon                                         done

demo@linux:~> tar xvzf tmp/backup-1.tar.gz  vol
vol/db-01.vol
vol/db-02.vol

demo@linux:~> rm vol/log-1.vol

demo@linux:~> dbvolextend -R -v -c eloqdb.cfg

ELOQUENCE DBVOLEXTEND (C) Copyright 2010 Marxmeier Software AG (B.08.10)

Reading configuration ...
Opening root volume
Restoring log volume /home/demo/vol/log-1.vol
Closing volume ...
done.

demo@linux:~> dbvoldump -c eloqdb.cfg

ELOQUENCE DBVOLDUMP (C) Copyright 2010 Marxmeier Software AG (B.08.10)

ID  Type Path
1   DATA /home/demo/vol/db-01.vol
2   DATA /home/demo/vol/db-02.vol
3   LOG  /home/demo/vol/log-1.vol

ID  Type  Cur.Sz  Ext.Sz  Max.Sz    Free    Used
1   DATA     2.5     1.0     0.0     0.8     1.7
2   DATA     2.5     1.0     0.0     2.4     0.1
3   LOG      2.5     1.0     0.0     2.5     0.0

demo@linux:~> ll log
total 416
-rw------- 1 demo users    127 2010-07-23 09:24 fw-0-1.log
-rw------- 1 demo users 420651 2010-07-23 09:31 fw-1-1.log


Important: Do not attempt to restart the database server before you
run dbrecover! This would increase the internal log generation number and
modify the volume files. The forward logs are then no longer matching and
cannot be applied without repeating the restore step.
(Note: incremental recovery is possible when starting the server in slave mode)
demo@linux:~> dbrecover -help

ELOQUENCE DBRECOVER (C) Copyright 2010 Marxmeier Software AG (B.08.10)
usage: dbrecover [options]
options:
 -t tmpdir    - directory to be used for temporary files
 -v           - verbose
 -d flags     - debug flags
 -c cfg       - configuration file name
 -b size      - Buffer cache size (MB)
 -T timestamp - recover until point in time (incl.)

timestamp formats:
 YYYY-MM-DD HH:MM:SS
 MM/DD/YYYY HH:MM:SS
 DD.MM.YYYY HH:MM:SS
 note: any character may be used to separate date and time
       time part is optional (defaults to 00:00:00)

demo@linux:~> dbrecover -v -c eloqdb.cfg -T "2010-07-23 09:29"

ELOQUENCE DBRECOVER (C) Copyright 2010 Marxmeier Software AG (B.08.10)
Opening root volume ...
Recovering until Fri Jul 23 09:29:00 2010 (incl.)
Recovering from forward-log ...
R1: processing forward-log file: '/home/demo/log/fw-1-1.log'
R1: stopping recovery on timestamp: 2010-07-23 09:29:16
1079 actions have been successfully recovered.
Database environment is now up-to-date until Fri Jul 23 09:28:22 2010.
done.

demo@linux:~> ll log
total 416
-rw------- 1 demo users    127 2010-07-23 09:24 fw-0-1.log
-rw------- 1 demo users 420651 2010-07-23 09:31 fw-1-1.log


(We move the "old" forward logs away, so that they don't interfere
with the new server startup. In our specific example this would not happen are we
did not exclude a larger number of logfiles from the recovery.)
demo@linux:~> mv log/fw* tmp


Start the recovered server and monitor startup messages...
demo@linux:~> /etc/init.d/eloq81 start demo
Starting eloqdb[demo] daemon                                         done

demo@linux:~> tail -20 eloqdb.log
Fri 23 09:31:31 ( 8122) D1: [2] Disconnected 127.0.0.1:38395 (TID 9)
Fri 23 09:31:40 ( 8122) T1: [4] Starting server shutdown ...
Fri 23 09:31:40 ( 8122) T1: [4] Exiting thread kernel ...
Fri 23 09:31:40 ( 8122) D1: Eloquence database server shutting down
Fri 23 09:31:41 ( 8122) D0: Eloquence data base server terminated

** Fri Jul 23 09:36:33 2010   Flags = [*1E2]

Fri 23 09:36:33 ( 8955) D1: Eloquence data base server initializing
Fri 23 09:36:33 ( 8956) D0: Server patch level B0810
Fri 23 09:36:33 ( 8956) D0: Server supports data encryption
Fri 23 09:36:33 ( 8956) D1: [0] /home/demo/vol/db-01.vol
Fri 23 09:36:33 ( 8956) D1: [1] /home/demo/vol/db-02.vol
Fri 23 09:36:33 ( 8956) D1: [2] /home/demo/vol/log-1.vol
Fri 23 09:36:33 ( 8956) C1: Setting up buffer cache: 8192 buffers
Fri 23 09:36:33 ( 8956) L0: created new forward-log segment (/home/demo/log/fw-3-1.log)
Fri 23 09:36:33 ( 8956) T1: Number of CPU cores in processor set is 1
Fri 23 09:36:33 ( 8956) D1: Communication buffer size = 1327104
Fri 23 09:36:33 ( 8956) D1: Communication buffer shmid = 360453
Fri 23 09:36:33 ( 8956) D0: Eloquence database server active

demo@linux:~> ll log
total 4
-rw------- 1 demo users 118 2010-07-23 09:36 fw-3-1.log

demo@linux:~> dbctl forwardlog status
Forward-logging is enabled.
Forward-log is '/home/demo/log/fw-3-1.log'.


A brief check if our recovered databases look OK...
demo@linux:~> dbdumpcat -t 31

ELOQUENCE DBDUMPCAT (C) Copyright 2010 Marxmeier Software AG (B.08.10)

-------------------------------------------
#31 sysdb (2 entries)
-------------------------------------------
|dbid|name                |flags   |nodeid|
-------------------------------------------
|11  |TOYDB               |04000000|100   |
|12  |TOYDB.TEST          |04000000|122   |
-------------------------------------------

demo@linux:~> dbinfo toydb

ELOQUENCE DBINFO (C) Copyright 2010 Marxmeier Software AG (B.08.10)

Processing database: toydb

SET NAME               RECLEN CAPACITY ENTRIES
---------------- --- - ------ -------- --------
PRODUCTS         001 M     30     1456       11
CUSTOMERS        002 M    260      229        8
ORDER-MASTER     003 A      8     1456       15
INVOICES         004 D     40     1149        1
ORDERS           005 D     18     1771       15
ORDER-DETAILS    006 D     20     1771       15

demo@linux:~> dbexport -s - toydb products

ELOQUENCE DBEXPORT (C) Copyright 2010 Marxmeier Software AG (B.08.10)

# DATABASE = TOYDB

# SET 1 = PRODUCTS
"A00003","POKER DICE SET",125,"10",500
"A00008","POSTER PAINTS",95,"30",1250
"A00009","COLOURING BOOK",65,"30",1000
"A00001","PACK OF CARDS",75,"10",1500
"A00010","ERASER GIFT SET",185,"30",1500
"A00002","LUDO SET",1250,"10",750
"A00005","15\" PINK RABBIT",1745,"20",200
"A00007","SET OF CRAYONS",175,"30",500
"A00004","12\" TEDDY BEAR",1525,"20",250
"A00006","SET OF PANDAS",2500,"20",150
"4711","eau de cologne",123,"xy",456


Did you notice that our product 4711 still has the original price 123
instead of the value 0 that we updated shortly before the dberase accident?
We did not specify seconds for dbrecover -T and thus missed the very last
database transaction. In real life the gap would typically be larger with
more users working on the database until we notice our accident and begin
taking corrective actions. Database auditing (see next section) could actually
be used in such a case to research such transactions in the forward logs.



Database Auditing
In this section we examine the forward logs collected during the
previous part of the demo. 
 This will allow us to get an idea about the
different options and features of the fwaudit utility...
demo@linux:~> fwaudit -help

ELOQUENCE FWAUDIT (C) Copyright 2010 Marxmeier Software AG (B.08.10)
usage: fwaudit [options] file [...]
options:
 -help       - show usage (this list)
 -o filename - write binary audit output to file (- for stdout)
 -c comment  - write clear-text comment into binary audit file
 -e expr     - specify filter expression
 -f filename - read filter expression from file
 -r          - print clear-text report
 -m          - print MEMO records
 -i number   - print values of the first 'number' items
 -I itemlist - print values of specified items (comma- or space-separated)
 -v          - print progress info / report details (-vv: more details)
 -x          - clear-text diagnostic output (hexdump format)
 -M          - use master key


The fwaudit -r option reports contents in text format...
demo@linux:~> fwaudit -r tmp/fw*log | more

ELOQUENCE FWAUDIT (C) Copyright 2010 Marxmeier Software AG (B.08.10)

SIGN-ON session:5 connection time: 2010-07-23 09:26:33
 protocol{a}os{Linux}ip{127.0.0.1}user{demo}login{public}conntime{1279869993}
 uid{1000}pid{8483}pname{query3k}
DBPUT TOYDB.PRODUCTS (#113) recno:11 session:5
 timestamp: 2010-07-23 09:26:53
SIGN-ON session:10 connection time: 2010-07-23 09:27:56
 protocol{a}os{Linux}ip{127.0.0.1}user{demo}login{public}conntime{1279870076}
 uid{1000}pid{8494}pname{dbimport -s tmp/toydb.export toydb.test}
DBPUT TOYDB.TEST.PRODUCTS (#135) recno:1 session:10
 timestamp: 2010-07-23 09:27:56
DBPUT TOYDB.TEST.PRODUCTS (#135) recno:2 session:10
 timestamp: 2010-07-23 09:27:56
DBPUT TOYDB.TEST.PRODUCTS (#135) recno:3 session:10
 timestamp: 2010-07-23 09:27:56
. . .


Option -e allows "filter expressions", e.g. to see
 only TOYDB transactions...
demo@linux:~> fwaudit -r -e "toydb.*" tmp/fw*log

ELOQUENCE FWAUDIT (C) Copyright 2010 Marxmeier Software AG (B.08.10)

SIGN-ON session:5 connection time: 2010-07-23 09:26:33
 protocol{a}os{Linux}ip{127.0.0.1}user{demo}login{public}conntime{1279869993}
 uid{1000}pid{8483}pname{query3k}
DBPUT TOYDB.PRODUCTS (#113) recno:11 session:5
 timestamp: 2010-07-23 09:26:53
SIGN-ON session:13 connection time: 2010-07-23 09:29:04
 protocol{a}os{Linux}ip{127.0.0.1}user{demo}login{public}conntime{1279870144}
 uid{1000}pid{8500}pname{query3k}
DBUPDATE TOYDB.PRODUCTS (#113) recno:11 session:13
 timestamp: 2010-07-23 09:29:16


We drill down to only DBUPDATEs and use -v for more details...
demo@linux:~> fwaudit -r -v -e "dbupdate and toydb.*" tmp/fw*log

ELOQUENCE FWAUDIT (C) Copyright 2010 Marxmeier Software AG (B.08.10)

processing file: tmp/fw-0-1.log

processing file: tmp/fw-1-1.log

SIGN-ON session:13 connection time: 2010-07-23 09:29:04
 protocol{a}os{Linux}ip{127.0.0.1}user{demo}login{public}conntime{1279870144}
 uid{1000}pid{8500}pname{query3k}

DBUPDATE TOYDB.PRODUCTS (#113) recno:11 session:13
 timestamp: 2010-07-23 09:29:16
  PRODUCT-NO            : "4711"
  PRODUCT-NAME          : "eau de cologne"
 -PRICE                 : 123
 +PRICE                 : 0
  PRODUCT-LINE          : "xy"
  QUANTITY              : 456

(The - and + prefixes denote old and new values)
Note that the above dbupdate shows the database change that was
not applied during our dbrecover run because of our selected target timestamp.
Based on the fwaudit info we could apply it manually, if needed.


We can also use -I to select the item names of interest...
demo@linux:~> fwaudit -r -e "toydb.*" -I product-no,price tmp/fw*log

ELOQUENCE FWAUDIT (C) Copyright 2010 Marxmeier Software AG (B.08.10)

SIGN-ON session:5 connection time: 2010-07-23 09:26:33
 protocol{a}os{Linux}ip{127.0.0.1}user{demo}login{public}conntime{1279869993}
 uid{1000}pid{8483}pname{query3k}

DBPUT TOYDB.PRODUCTS (#113) recno:11 session:5
 timestamp: 2010-07-23 09:26:53
  PRODUCT-NO            : "4711"
  PRICE                 : 123

SIGN-ON session:13 connection time: 2010-07-23 09:29:04
 protocol{a}os{Linux}ip{127.0.0.1}user{demo}login{public}conntime{1279870144}
 uid{1000}pid{8500}pname{query3k}

DBUPDATE TOYDB.PRODUCTS (#113) recno:11 session:13
 timestamp: 2010-07-23 09:29:16
  PRODUCT-NO            : "4711"
 -PRICE                 : 123
 +PRICE                 : 0


The -o option can be used to archive only the audit information from
the forwarg-logs, which typically also contain recovery related data. The
resulting binary audit format files are more compact and can also collapse
multiple forward logfiles into a single audit archive...
demo@linux:~> YMD=$(date +'%Y%m%d')

demo@linux:~> echo $YMD
20100723

demo@linux:~> fwaudit -v -o tmp/audit-$YMD.log  tmp/fw*.log

ELOQUENCE FWAUDIT (C) Copyright 2010 Marxmeier Software AG (B.08.10)

processing file: tmp/fw-0-1.log
processing file: tmp/fw-1-1.log

demo@linux:~> ll tmp/fw*log tmp/audit*log
-rw-r--r-- 1 demo users   5732 2010-07-23 09:46 tmp/audit-20100723.log
-rw------- 1 demo users    127 2010-07-23 09:24 tmp/fw-0-1.log
-rw------- 1 demo users 420651 2010-07-23 09:31 tmp/fw-1-1.log


Here another nice little fwaudit example, providing DBPUT statistics...
demo@linux:~> fwaudit -r tmp/audit-$YMD.log | awk '$1=="DBPUT" {print $1 FS $2}' | sort | uniq -c

ELOQUENCE FWAUDIT (C) Copyright 2010 Marxmeier Software AG (B.08.10)
      1 DBPUT TOYDB.PRODUCTS
      8 DBPUT TOYDB.TEST.CUSTOMERS
      1 DBPUT TOYDB.TEST.INVOICES
     15 DBPUT TOYDB.TEST.ORDER-DETAILS
     15 DBPUT TOYDB.TEST.ORDERS
     11 DBPUT TOYDB.TEST.PRODUCTS


Database Server Replication
In this section we will configure our small database server for replication.
For the sake of simplicity we will place the slave server on the same system into
a subdirectory of the demo user. We will thus need to adjust the config file of
the slave server to use separate directories for its files and different TCP port
numbers for its services. When running master server and slave server on separate
systems, this might not be neccessary.
We first change the master server config from standalone to master role.

We already enabled FwLog earlier in this demo, so this change is not needed here.
(we use rcs as convenient method to track config changes; not required)
demo@linux:~> ci -l eloqdb.cfg
eloqdb.cfg,v  <--  eloqdb.cfg
new revision: 1.3; previous revision: 1.2
enter log message, terminated with single '.' or end of file:
>> config with forward logging, but before replication
>> .
done


(we modified the config file with vi here, rcsdiff shows the change)

demo@linux:~> rcsdiff eloqdb.cfg
===================================================================
RCS file: eloqdb.cfg,v
retrieving revision 1.3
diff -r1.3 eloqdb.cfg
296c296
< #Role = Standalone
---
> Role = Master


Config change needs server restart for activation...
demo@linux:~> /etc/init.d/eloq81 restart demo
Stopping eloqdb[demo] daemon                                         done
Starting eloqdb[demo] daemon                                         done

demo@linux:~> tail -20 eloqdb.log
Fri 23 09:50:02 ( 9082) D1: Eloquence database server shutting down
Fri 23 09:50:03 ( 9082) D0: Eloquence data base server terminated

** Fri Jul 23 09:50:04 2010   Flags = [*1E2]

Fri 23 09:50:04 ( 9230) D1: Eloquence data base server initializing
Fri 23 09:50:04 ( 9231) D0: Server patch level B0810
Fri 23 09:50:04 ( 9231) D0: Server is configured as a replication MASTER server
Fri 23 09:50:04 ( 9231) D0: Server supports data encryption
Fri 23 09:50:04 ( 9231) D1: [0] /home/demo/vol/db-01.vol
Fri 23 09:50:04 ( 9231) D1: [1] /home/demo/vol/db-02.vol
Fri 23 09:50:04 ( 9231) D1: [2] /home/demo/vol/log-1.vol
Fri 23 09:50:04 ( 9231) C1: Setting up buffer cache: 8192 buffers
Fri 23 09:50:04 ( 9231) L1: volume recovery: state of committed transactions is OK
Fri 23 09:50:04 ( 9231) L1: volume recovery: state of volume is OK
Fri 23 09:50:04 ( 9231) L0: created new forward-log segment (/home/demo/log/fw-4-1.log)
Fri 23 09:50:04 ( 9231) T1: Number of CPU cores in processor set is 1
Fri 23 09:50:04 ( 9231) D1: Communication buffer size = 1327104
Fri 23 09:50:04 ( 9231) D1: Communication buffer shmid = 425989
Fri 23 09:50:04 ( 9231) D0: Eloquence database server active


Now we prepare a subdirectory for the slave server, copy our master
server config as a starting point, and perform several adjustments, especially
setting the Role to "slave". You can see the changes in rcsdiff output...

demo@linux:~> mkdir slave

demo@linux:~> cp eloqdb.cfg slave

demo@linux:~> cd slave

demo@linux:~/slave> ci -l eloqdb.cfg
eloqdb.cfg,v  <--  eloqdb.cfg
enter description, terminated with single '.' or end of file:
NOTE: This is NOT the log message!
>> slave config based on master config
>> .
initial revision: 1.1
done


(imagine use of your favourite editor here ;-)

demo@linux:~/slave> rcsdiff eloqdb.cfg
===================================================================
RCS file: eloqdb.cfg,v
retrieving revision 1.1
diff -r1.1 eloqdb.cfg
29c29
< Title = demo server
---
> Title = demo slave server
41,42c41,42
< Service = 3000
< ServiceHttp = 3080
---
> Service = 4000
> ServiceHttp = 4080
114c114
< LogFile = /home/demo/eloqdb.log
---
> LogFile = /home/demo/slave/eloqdb.log
296c296
< Role = Master
---
> Role = Slave
479c479
< FwLog = /home/demo/log/fw-%N.log
---
> FwLog = /home/demo/slave/log/fw-%N.log
531,533c531,533
< Root = /home/demo/vol/db-01.vol
< Vol02 = /home/demo/vol/db-02.vol
< Log03 = /home/demo/vol/log-1.vol
---
> Root = /home/demo/slave/vol/db-01.vol
> Vol02 = /home/demo/slave/vol/db-02.vol
> Log03 = /home/demo/slave/vol/log-1.vol


demo@linux:~/slave> /etc/init.d/eloq81 info demo-slave
 eloqdb instance id = demo-slave
  configuration file = /home/demo/slave/eloqdb.cfg
  service = 4000
  args =
  run prefix =
  automatic start = 0
  user = demo
  eloqdb = /opt/eloquence/8.1/bin/eloqdb


Next we clone a copy of the master server by using online
backup mode for copying the data volumes, create a clean log volume
and bring up the slave server. In real life you could also restore
the slave volumes from your most recent backup, as long as all the
forward logs matching the backup time are still available...
demo@linux:~/slave> mkdir vol log

demo@linux:~/slave> dbctl -s 3000 -u dba backup start
On-line backup mode has been started.

demo@linux:~/slave> cp ../vol/db*.vol ./vol

demo@linux:~/slave> ll vol
total 5120
-rw------- 1 demo users 2621440 2010-07-23 09:54 db-01.vol
-rw------- 1 demo users 2621440 2010-07-23 09:54 db-02.vol

demo@linux:~/slave> dbctl -s 3000 -u dba backup stop
On-line backup mode has been stopped.

demo@linux:~/slave> ll
total 56
-rw-r--r-- 1 demo users 21496 2010-07-23 09:52 eloqdb.cfg
-r--r--r-- 1 demo users 21685 2010-07-23 09:51 eloqdb.cfg,v
drwxr-xr-x 2 demo users  4096 2010-07-23 09:54 log
drwxr-xr-x 2 demo users  4096 2010-07-23 09:54 vol

demo@linux:~/slave> ll vol
total 5120
-rw------- 1 demo users 2621440 2010-07-23 09:54 db-01.vol
-rw------- 1 demo users 2621440 2010-07-23 09:54 db-02.vol

demo@linux:~/slave> dbvolextend -R -vc eloqdb.cfg

ELOQUENCE DBVOLEXTEND (C) Copyright 2010 Marxmeier Software AG (B.08.10)

Reading configuration ...
Opening root volume
Restoring log volume /home/demo/slave/vol/log-1.vol
Closing volume ...
done.

demo@linux:~/slave> ll vol
total 7680
-rw------- 1 demo users 2621440 2010-07-23 09:55 db-01.vol
-rw------- 1 demo users 2621440 2010-07-23 09:54 db-02.vol
-rw------- 1 demo users 2621440 2010-07-23 09:55 log-1.vol


With config and volumes in place, we start the slave server...
demo@linux:~/slave> /etc/init.d/eloq81 start demo-slave
Starting eloqdb[demo-slave] daemon                                   done

demo@linux:~/slave> tail -20 eloqdb.log

** Fri Jul 23 09:55:44 2010   Flags = [*1E2]

Fri 23 09:55:44 ( 9691) D1: Eloquence data base server initializing
Fri 23 09:55:44 ( 9692) D0: Server patch level B0810
Fri 23 09:55:44 ( 9692) D0: Server is configured as a replication SLAVE server
Fri 23 09:55:44 ( 9692) D0: Server supports data encryption
Fri 23 09:55:44 ( 9692) D1: [0] /home/demo/slave/vol/db-01.vol
Fri 23 09:55:44 ( 9692) D1: [1] /home/demo/slave/vol/db-02.vol
Fri 23 09:55:44 ( 9692) D1: [2] /home/demo/slave/vol/log-1.vol
Fri 23 09:55:44 ( 9692) C1: Setting up buffer cache: 8192 buffers
Fri 23 09:55:45 ( 9692) T1: Number of CPU cores in processor set is 1
Fri 23 09:55:45 ( 9692) D1: Communication buffer size = 1327104
Fri 23 09:55:45 ( 9692) D1: Communication buffer shmid = 458758
Fri 23 09:55:45 ( 9692) D0: Eloquence database server active

demo@linux:~/slave> /etc/init.d/eloq81 status
eloqsd process is not active                                         unused
eloqdb[eloqdb] process is not active                                 unused
eloqdb[demo] process is active (pid 9231)                            running
eloqdb[demo-slave] process is active (pid 9692)                      running



We can use dbctl to check the replication status of master
and slave servers. In our case, both show the same checkpoint and
timestamp because there was no database activity on our master
while we set up the slave. In real life the master server would
contents would have "advanced in time", so that the slave server
initially lags behind.
demo@linux:~/slave> dbctl -s 3000 replication status
Server is configured as MASTER
Last checkpoint is 5-1.1 (2010-07-23 09:54:21)
Forward-logging is enabled
Forward-log is '/home/demo/log/fw-5-1.log'

demo@linux:~/slave> dbctl -s 4000 replication status
Server is configured as SLAVE
Replication is inactive
Last checkpoint is 5-1.1 (2010-07-23 09:54:21)
Forward-logging is enabled


To start replication between the two servers, we run the dbrepl
utility on the master. In this demo we used a separate terminal so we
can see its diagnostic messages; in real life, dbrepl would be run as
a "nohup" background process.
When started, dbrepl retrieves the replication status from the
slave server, locates the appropriate starting point in the forward-logs
of the master, and begins replicating transactions. After catching up
with the master server (if there was any backlog), it follows new master
transactions close to real time.

# ... (separate terminal window)
# 
# demo@linux:~> dbrepl -v -c eloqdb.cfg :4000
# R1: processing forward-log file: '/home/demo/log/fw-5-1.log'
# R1: found synchronization point with slave server
# R1: slave server is up-to-date until 2010-07-23 09:54:21
# 
# ... (dbrepl continues running)


To verify the replication, we use query3k or any other utility to
perform some database update on the master server. We can then use query3k
or dbexport or any other appropriate utility to check if the update has
been propagated to the slave server correctly...
demo@linux:~/slave> EQ_DBSERVER=:3000 query3k
B.08.10.00 Eloquence QUERY3K  FRI, JUL 23, 2010,  9:59 AM
Copyright 2004-2010 Marxmeier Software AG
Copyright 2004 Hewlett-Packard Development Company, L.P.

>base=toydb
PASSWORD = >>
MODE = >>1
>add products
PRODUCT-NO      =>>4712
PRODUCT-NAME    =>>dont care
PRICE           =>>321
PRODUCT-LINE    =>>xx
QUANTITY        =>>789

PRODUCT-NO      =>>//
>exit

demo@linux:~/slave> EQ_DBSERVER=:4000 dbexport -s - toydb products

ELOQUENCE DBEXPORT (C) Copyright 2010 Marxmeier Software AG (B.08.10)

# DATABASE = TOYDB

# SET 1 = PRODUCTS
"A00003","POKER DICE SET",125,"10",500
"A00008","POSTER PAINTS",95,"30",1250
"A00009","COLOURING BOOK",65,"30",1000
"A00001","PACK OF CARDS",75,"10",1500
"A00010","ERASER GIFT SET",185,"30",1500
"A00002","LUDO SET",1250,"10",750
"A00005","15\" PINK RABBIT",1745,"20",200
"A00007","SET OF CRAYONS",175,"30",500
"A00004","12\" TEDDY BEAR",1525,"20",250
"A00006","SET OF PANDAS",2500,"20",150
"4711","eau de cologne",123,"xy",456
"4712","dont care",321,"xx",789


dbctl also shows an updated replication status and timestamp now...
demo@linux:~/slave> dbctl -s 3000 replication status
Server is configured as MASTER
Last checkpoint is 5-1.14 (2010-07-23 10:00:04)
Forward-logging is enabled
Forward-log is '/home/demo/log/fw-5-1.log'

demo@linux:~/slave> dbctl -s 4000 replication status
Server is configured as SLAVE
Replication is active
Last checkpoint is 5-1.14 (2010-07-23 10:00:04)
Forward-logging is enabled
Forward-log is '/home/demo/slave/log/fw-5-1.log'


When using forward logging and replication, you have to keep in mind to
implement appropriate scripts and procedures for housekeeping the forward-logs
in such a way that they are not deleted before dbrepl has processed them.
If you are also using the FwLog option on the slave server, to maintain
replicated copies of the master forward-logs on the slave (in addition to the
replicated databases), you will also need to implement appropriate housekeeping
procedures on the slave system.
demo@linux:~/slave> cd .. ; ll log slave/log
log:
total 12
-rw------- 1 demo users  859 2010-07-23 09:50 fw-3-1.log
-rw------- 1 demo users  127 2010-07-23 09:54 fw-4-1.log
-rw------- 1 demo users 1037 2010-07-23 10:01 fw-5-1.log

slave/log:
total 4
-rw------- 1 demo users 1037 2010-07-23 10:01 fw-5-1.log





(End of Demo)






Documentation References





Forward Logging


http://eloquence.marxmeier.com/support/B0800/doc/fwlog/index.html


Database Auditing


http://eloquence.marxmeier.com/support/B0800/doc/audit/index.html


Server Replication


http://eloquence.marxmeier.com/support/B0800/doc/repl/index.html







http status display


http://eloquence.marxmeier.com/support/B0800/doc/http-status/index.html


Database server statistics


http://eloquence.marxmeier.com/support/B0800/doc/stats/index.html


dbctl utility


http://eloquence.marxmeier.com/support/B0800/doc/dbctl/index.html