test_log2sql.py #12

  • //
  • guest/
  • robert_cowham/
  • perforce/
  • utils/
  • log_analysis/
  • test_log2sql.py
  • View
  • Commits
  • Open Download .zip Download (23 KB)
# -*- encoding: UTF8 -*-
# Test harness for JobsCmdFilter.py

from __future__ import print_function

import sys
import unittest
import os
import re
import sqlite3
sys.path.insert(0, os.path.dirname(os.path.abspath(__file__)))

from log2sql import Log2sql

python3 = sys.version_info[0] >= 3

if python3:
    from io import StringIO
else:
    from StringIO import StringIO

fileHeader = """CREATE DATABASE IF NOT EXISTS testdb;
USE testdb;
DROP TABLE IF EXISTS process;
CREATE TABLE process (processkey CHAR(32) NOT NULL, lineNumber INT NOT NULL, pid INT NOT NULL, startTime DATETIME NOT NULL,endTime DATETIME NULL, computedLapse FLOAT NULL,completedLapse FLOAT NULL, user TEXT NOT NULL, workspace TEXT NOT NULL, ip TEXT NOT NULL, app TEXT NOT NULL, cmd TEXT NOT NULL, args TEXT NULL, uCpu INT NULL, sCpu INT NULL, diskIn INT NULL, diskOut INT NULL, ipcIn INT NULL, ipcOut INT NULL, maxRss INT NULL, pageFaults INT NULL, rpcMsgsIn INT NULL, rpcMsgsOut INT NULL, rpcSizeIn INT NULL, rpcSizeOut INT NULL, rpcHimarkFwd INT NULL, rpcHimarkRev INT NULL, rpcSnd FLOAT NULL, rpcRcv FLOAT NULL, running INT NULL, error TEXT NULL, PRIMARY KEY (processkey, lineNumber));
DROP TABLE IF EXISTS tableUse;
CREATE TABLE tableUse (processkey CHAR(32) NOT NULL, lineNumber INT NOT NULL, tableName VARCHAR(255) NOT NULL, pagesIn INT NULL, pagesOut INT NULL, pagesCached INT NULL, readLocks INT NULL, writeLocks INT NULL, getRows INT NULL, posRows INT NULL, scanRows INT NULL, putRows int NULL, delRows INT NULL, totalReadWait INT NULL, totalReadHeld INT NULL, totalWriteWait INT NULL, totalWriteHeld INT NULL, maxReadWait INT NULL, maxReadHeld INT NULL, maxWriteWait INT NULL, maxWriteHeld INT NULL, PRIMARY KEY (processkey, lineNumber, tableName));
BEGIN TRANSACTION;
"""

class MyOptions():
    def __init__(self, dbname, logname, sql=False):
        self.dbname = dbname
        self.logname = logname
        self.sql = sql

class TestLogParser(unittest.TestCase):

    def __init__(self, methodName='runTest'):
        super(TestLogParser, self).__init__(methodName=methodName)

    def assertRegex(self, *args, **kwargs):
        if python3:
            return super(TestLogParser, self).assertRegex(*args, **kwargs)
        else:
            return super(TestLogParser, self).assertRegexpMatches(*args, **kwargs)

    def setUp(self):
        pass

    def tearDown(self):
        pass

    def testClientLockRecords(self):
        "Extra record for client lock"

        optionsText = MyOptions("testdb", "")
        optionsSQL = MyOptions("testdb", "", sql=True)
        dbname = "%s.db" % optionsSQL.dbname

        # Test parsing of sync with client lock info
        input = """
Perforce server info:
	2017/02/15 13:46:42 pid 81805 bruno@robert_cowham-dvcs-1487082773 10.62.185.98 [p4/2016.2/LINUX26X86_64/1468155] 'user-client -d -f bruno.139631598948304.irp210-h03'
Perforce server info:
	2017/02/15 13:46:42 pid 81805 bruno@robert_cowham-dvcs-1487082773 10.62.185.98 [p4/2016.2/LINUX26X86_64/1468155] 'user-client -d -f bruno.139631598948304.irp210-h03'
--- clients/bruno%2E139631598948304%2Eirp210-h03(W)
---   total lock wait+held read/write 0ms+0ms/0ms+9ms

Perforce server info:
	2017/02/15 13:46:42 pid 81805 completed .009s 8+1us 0+1408io 0+0net 4088k 0pf
Perforce server info:
	2017/02/15 13:46:42 pid 81805 bruno@robert_cowham-dvcs-1487082773 10.62.185.98 [p4/2016.2/LINUX26X86_64/1468155] 'user-client -d -f bruno.139631598948304.irp210-h03'
--- lapse .009s
--- usage 8+1us 0+1408io 0+0net 4088k 0pf
--- rpc msgs/size in+out 0+1/0mb+0mb himarks 318788/318788 snd/rcv .001s/.002s
--- db.user
---   pages in+out+cached 3+0+2
---   locks read/write 1/0 rows get+pos+scan put+del 1+0+0 0+0
"""
        md5 = "5f1deb0b9ceec4f4906685722f6c8744"
        if python3:
            md5 = "5f1deb0b9ceec4f4906685722f6c8744"
        expected = """INSERT IGNORE INTO process VALUES ("%s",5,81805,"2017-02-15 13:46:42",NULL,NULL,NULL,"bruno","robert_cowham-dvcs-1487082773","10.62.185.98","p4/2016.2/LINUX26X86_64/1468155","user-client","-d -f bruno.139631598948304.irp210-h03",NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,1,NULL);
UPDATE process SET uCpu=NULL,sCpu=NULL,diskIn=NULL,diskOut=NULL,ipcIn=NULL,ipcOut=NULL,maxRss=NULL,pageFaults=NULL,rpcMsgsIn=NULL,rpcMsgsOut=NULL,rpcSizeIn=NULL,rpcSizeOut=NULL,rpcHimarkFwd=NULL,rpcHimarkRev=NULL,rpcSnd=NULL,rpcRcv=NULL,error=NULL WHERE processKey = "%s" and lineNumber = 5;
UPDATE process SET endTime=startTime WHERE processKey = "%s" and lineNumber = 5 and endTime IS NULL;
INSERT IGNORE INTO process VALUES ("%s",12,81805,"2017-02-15 13:46:42",NULL,NULL,NULL,"bruno","robert_cowham-dvcs-1487082773","10.62.185.98","p4/2016.2/LINUX26X86_64/1468155","user-client","-d -f bruno.139631598948304.irp210-h03",0,1,0,0,318788,318788,.001,.002,8,1,0,1408,0,0,4088,0,1,NULL);
UPDATE process SET uCpu=8,sCpu=1,diskIn=0,diskOut=1408,ipcIn=0,ipcOut=0,maxRss=4088,pageFaults=0,rpcMsgsIn=0,rpcMsgsOut=1,rpcSizeIn=0,rpcSizeOut=0,rpcHimarkFwd=318788,rpcHimarkRev=318788,rpcSnd=.001,rpcRcv=.002,error=NULL WHERE processKey = "%s" and lineNumber = 12;
UPDATE process SET endTime=startTime WHERE processKey = "%s" and lineNumber = 12 and endTime IS NULL;
INSERT IGNORE INTO tableUse VALUES ("%s",12,"user",3,0,2,1,0,1,0,0,0,0,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL);
COMMIT;
BEGIN TRANSACTION;
""" % (md5, md5, md5, md5, md5, md5, md5)
        saved_stdoutput = StringIO()

        log2sql = Log2sql(optionsText, instream=StringIO(input), outstream=saved_stdoutput)
        log2sql.processLog()
        actual = saved_stdoutput.getvalue()
        self.assertEqual(fileHeader, actual[:len(fileHeader)])
        self.assertEqual(expected, actual[len(fileHeader):])

        # Test with SQL
        if os.path.exists(dbname):
            os.remove(dbname)
        log2sql = Log2sql(optionsSQL, instream=StringIO(input), outstream=saved_stdoutput)
        log2sql.processLog()
        conn = sqlite3.connect(dbname)
        c = conn.cursor()
        c.execute('SELECT * from Process;')
        rows = c.fetchall()
        self.assertEqual(len(rows), 2)  #TODO: should really be one
        row = rows[0]
        self.assertEqual(row[0], md5)
        self.assertEqual(row[3], '"2017-02-15 13:46:42"')
        self.assertEqual(row[4], '"2017-02-15 13:46:42"')
        conn.close()

    def testBasicParsing(self):
        "simple parsing"

        optionsText = MyOptions("testdb", "")
        optionsSQL = MyOptions("testdb", "", sql=True)
        dbname = "%s.db" % optionsSQL.dbname

        # Test parsing of sync with 3 log entries
        input = """
Perforce server info:
	2015/09/02 15:23:09 pid 1616 robert@robert-test 127.0.0.1 [Microsoft Visual Studio 2013/12.0.21005.1] 'user-sync //...'
Perforce server info:
	2015/09/02 15:23:09 pid 1616 compute end .031s
Perforce server info:
	2015/09/02 15:23:09 pid 1616 completed .031s
"""
        md5 = "51ae6850c357585e594720f7efe9bfc0"
        if python3:
            md5 = "51ae6850c357585e594720f7efe9bfc0"
        expected = """INSERT IGNORE INTO process VALUES ("%s",3,1616,"2015-09-02 15:23:09",NULL,NULL,NULL,"robert","robert-test","127.0.0.1","Microsoft Visual Studio 2013/12.0.21005.1","user-sync","//...",NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,0,NULL);
COMMIT;
BEGIN TRANSACTION;
""" % md5
        saved_stdoutput = StringIO()

        log2sql = Log2sql(optionsText, instream=StringIO(input), outstream=saved_stdoutput)
        log2sql.processLog()
        actual = saved_stdoutput.getvalue()
        self.assertEqual(fileHeader, actual[:len(fileHeader)])
        self.assertEqual(expected, actual[len(fileHeader):])

        # Test with SQL
        if os.path.exists(dbname):
            os.remove(dbname)
        log2sql = Log2sql(optionsSQL, instream=StringIO(input), outstream=saved_stdoutput)
        log2sql.processLog()
        conn = sqlite3.connect(dbname)
        c = conn.cursor()
        c.execute('SELECT * from Process;')
        rows = c.fetchall()
        self.assertEqual(len(rows), 1)
        row = rows[0]
        self.assertEqual(row[0], md5)
        self.assertEqual(row[3], '"2015-09-02 15:23:09"')
        conn.close()


        # Same as above with invalid Unicode strings
        input = """
Perforce server info:
	2015/09/02 15:23:09 pid 1616 robert@robert-test 127.0.0.1 [Microsoft® Visual Studio® 2013/12.0.21005.1] 'user-sync //...'
Perforce server info:
	2015/09/02 15:23:09 pid 1616 compute end .031s
Perforce server info:
	2015/09/02 15:23:09 pid 1616 completed .031s
"""
        md5 = "4f808949ed1932ddfeff8db1ce9c6b14"
        expected = """INSERT IGNORE INTO process VALUES ("%s",3,1616,"2015-09-02 15:23:09",NULL,NULL,NULL,"robert","robert-test","127.0.0.1","Microsoft\xc2\xae Visual Studio\xc2\xae 2013/12.0.21005.1","user-sync","//...",NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,0,NULL);
COMMIT;
BEGIN TRANSACTION;
""" % md5
        if python3:
            md5 = "925f8e5b6ccff960001f246225feb562"
            expected = """INSERT IGNORE INTO process VALUES ("%s",3,1616,"2015-09-02 15:23:09",NULL,NULL,NULL,"robert","robert-test","127.0.0.1","Microsoft® Visual Studio® 2013/12.0.21005.1","user-sync","//...",NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,0,NULL);
COMMIT;
BEGIN TRANSACTION;
""" % md5
        saved_stdoutput = StringIO()

        log2sql = Log2sql(optionsText, instream=StringIO(input), outstream=saved_stdoutput)
        log2sql.processLog()
        actual = saved_stdoutput.getvalue()
        self.assertEqual(fileHeader, actual[:len(fileHeader)])
        print("Expected:\n%s" % expected)
        print("Actual:\n%s" % actual[len(fileHeader):])
        self.assertEqual(expected, actual[len(fileHeader):])

        # Test with SQL
        if os.path.exists(dbname):
            os.remove(dbname)
        log2sql = Log2sql(optionsSQL, instream=StringIO(input), outstream=saved_stdoutput)
        log2sql.processLog()
        conn = sqlite3.connect(dbname)
        c = conn.cursor()
        c.execute('SELECT * from Process;')
        rows = c.fetchall()
        self.assertEqual(len(rows), 1)
        row = rows[0]
        self.assertEqual(row[0], md5)
        self.assertEqual(row[3], '"2015-09-02 15:23:09"')
        conn.close()

    def testThreeRecords(self):
        "Extra record for client lock"

        optionsText = MyOptions("testdb", "")
        optionsSQL = MyOptions("testdb", "", sql=True)
        dbname = "%s.db" % optionsSQL.dbname

        # Test parsing of sync with 3 log entries

        input = """
Perforce server info:
	2015/09/02 15:23:11 pid 1616 robert@robert-test 127.0.0.1 [Microsoft Visual Studio 2013/12.0.21005.1] 'user-changes -c robert-test -m 1 -s pending -u robert'
Perforce server info:
	2015/09/02 15:23:11 pid 1616 compute end .047s
Perforce server info:
	2015/09/02 15:23:11 pid 1616 completed .047s
"""
        md5 = "df655d67bf61ab0e6e53d67bb0fe3674"
        if python3:
            md5 = "df655d67bf61ab0e6e53d67bb0fe3674"
        expected = """INSERT IGNORE INTO process VALUES ("%s",3,1616,"2015-09-02 15:23:11",NULL,NULL,NULL,"robert","robert-test","127.0.0.1","Microsoft Visual Studio 2013/12.0.21005.1","user-changes","-c robert-test -m 1 -s pending -u robert",NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,0,NULL);
COMMIT;
BEGIN TRANSACTION;
""" % md5
        saved_stdoutput = StringIO()
        log2sql = Log2sql(optionsText, instream=StringIO(input), outstream=saved_stdoutput)
        log2sql.processLog()
        actual = saved_stdoutput.getvalue()
        self.assertEqual(fileHeader, actual[:len(fileHeader)])
        self.assertEqual(expected, actual[len(fileHeader):])

        # Test with SQL
        if os.path.exists(dbname):
            os.remove(dbname)
        log2sql = Log2sql(optionsSQL, instream=StringIO(input), outstream=saved_stdoutput)
        log2sql.processLog()
        conn = sqlite3.connect(dbname)
        c = conn.cursor()
        c.execute('SELECT * from Process;')
        rows = c.fetchall()
        self.assertEqual(len(rows), 1)
        row = rows[0]
        self.assertEqual(row[0], md5)
        self.assertEqual(row[3], '"2015-09-02 15:23:11"')
        conn.close()

    def testSwarm(self):
        "Swarm style entry"

        optionsText = MyOptions("testdb", "")
        optionsSQL = MyOptions("testdb", "", sql=True)
        dbname = "%s.db" % optionsSQL.dbname

        # Test parsing of swarm style entry
        input = r"""
Perforce server info:
	2016/12/21 08:39:39 pid 14769 perforce@~tmp.1482305462.13038.585a2fb6041cc1.60954329 192.168.18.31 [SWARM/2016.2/1446446] 'user-counter -u swarm-activity-fffec3dd {"type":"change","link":["change",{"change":1005814}],"user":"sahaltran05","action":"committed","target":"change 1005814","preposition":"into","description":"Mac address filtering and fixing the naming collision for the SSH and telnet libraries\n","details":null,"topic":"changes\/1005814","depotFile":null,"time":1482305978,"behalfOf":null,"projects":{"sah-automation":["sah-tests"]},"streams":["user-sahaltran05","personal-sahaltran05","project-sah-automation","group-p4altran","group-sah_app","group-sah_commun_modules","group-sah_components","group-sah_demo","group-sah_hardco","group-sah_nanterre","group-sah_nanterre_opensource","group-sah_opensource","group-sah_stbconfig","group-sah_stbconfig_dev","group-sah_system","group-sah_third_party","group-sah_validation","group-sah_wijgmaal","personal-sah4011"],"change":1005814}'
Perforce server info:
	2016/12/21 08:39:39 pid 14769 completed .003s 4+0us 0+16io 0+0net 6432k 0pf
"""
        md5 = "fc41244739bdc71e81bcabbfc93124da"
        if python3:
            md5 = "fc41244739bdc71e81bcabbfc93124da"
        expected = """INSERT IGNORE INTO process VALUES ("%s",3,14769,"2016-12-21 08:39:39","2016-12-21 08:39:39",NULL,0.003,"perforce","~tmp.1482305462.13038.585a2fb6041cc1.60954329","192.168.18.31","SWARM/2016.2/1446446","user-counter","-u swarm-activity-fffec3dd",NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,0,NULL);
COMMIT;
BEGIN TRANSACTION;
""" % md5
        saved_stdoutput = StringIO()
        log2sql = Log2sql(optionsText, instream=StringIO(input), outstream=saved_stdoutput)
        log2sql.processLog()
        actual = saved_stdoutput.getvalue()
        self.assertEqual(fileHeader, actual[:len(fileHeader)])
        self.assertEqual(expected, actual[len(fileHeader):])

        # Test with SQL
        if os.path.exists(dbname):
            os.remove(dbname)
        log2sql = Log2sql(optionsSQL, instream=StringIO(input), outstream=saved_stdoutput)
        log2sql.processLog()
        conn = sqlite3.connect(dbname)
        c = conn.cursor()
        c.execute('SELECT * from Process;')
        rows = c.fetchall()
        self.assertEqual(len(rows), 1)
        row = rows[0]
        self.assertEqual(row[0], md5)
        self.assertEqual(row[3], '"2016-12-21 08:39:39"')
        self.assertEqual(row[4], '"2016-12-21 08:39:39"')
        conn.close()

    def testGitFusion(self):
        "GitFusion stule entry"

        optionsText = MyOptions("testdb", "")
        optionsSQL = MyOptions("testdb", "", sql=True)
        dbname = "%s.db" % optionsSQL.dbname

        # Test parsing of git-fusion style entry
        input = r"""
Perforce server info:
	2016/10/19 12:01:08 pid 10664 git-fusion-user@GF-TRIGGER-567d67de-962 10.100.104.199 [p4/2016.1/NTX64/1396108] 'user-key git-fusion-reviews-common-lock-owner {"server_id": "p4gf_submit_trigger", "process_id": 5068, "start_time": "2016-10-19 12:01:08"}'
--- lapse .875s
--- rpc msgs/size in+out 2+3/0mb+0mb himarks 523588/523588 snd/rcv .000s/.015s
--- db.nameval
---   pages in+out+cached 6+4+4
---   locks read/write 0/1 rows get+pos+scan put+del 0+0+0 1+0
---   total lock wait+held read/write 0ms+0ms/16ms+15ms
--- db.user
---   pages in+out+cached 4+0+3
---   locks read/write 1/0 rows get+pos+scan put+del 1+0+0 0+0
---   total lock wait+held read/write 0ms+16ms/0ms+0ms
--- db.group
---   pages in+out+cached 7+0+6
---   locks read/write 1/0 rows get+pos+scan put+del 0+3+67 0+0
---   total lock wait+held read/write 0ms+15ms/0ms+0ms
--- db.trigger
---   pages in+out+cached 21+0+20
---   locks read/write 1/0 rows get+pos+scan put+del 0+1+486 0+0
---   total lock wait+held read/write 0ms+47ms/0ms+0ms
--- db.protect
---   pages in+out+cached 282+0+96
---   locks read/write 1/0 rows get+pos+scan put+del 0+1+14495 0+0
---   total lock wait+held read/write 0ms+641ms/0ms+0ms
Perforce server info:
	2016/10/19 12:01:09 pid 10664 completed .844s
"""
        md5 = "afafbfd330e2378418bfb4025a86617c"
        expected = """INSERT IGNORE INTO process VALUES ("%s",3,10664,"2016-10-19 12:01:08",NULL,NULL,NULL,"git-fusion-user","GF-TRIGGER-567d67de-962","10.100.104.199","p4/2016.1/NTX64/1396108","user-key","git-fusion-reviews-common-lock-owner",2,3,0,0,523588,523588,.000,.015,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,0,NULL);
UPDATE process SET uCpu=NULL,sCpu=NULL,diskIn=NULL,diskOut=NULL,ipcIn=NULL,ipcOut=NULL,maxRss=NULL,pageFaults=NULL,rpcMsgsIn=2,rpcMsgsOut=3,rpcSizeIn=0,rpcSizeOut=0,rpcHimarkFwd=523588,rpcHimarkRev=523588,rpcSnd=.000,rpcRcv=.015,error=NULL WHERE processKey = "%s" and lineNumber = 3;
UPDATE process SET endTime=startTime WHERE processKey = "%s" and lineNumber = 3 and endTime IS NULL;
INSERT IGNORE INTO tableUse VALUES ("%s",3,"nameval",6,4,4,0,1,0,0,0,1,0,0,0,16,15,0,0,16,15);
INSERT IGNORE INTO tableUse VALUES ("%s",3,"protect",282,0,96,1,0,0,1,14495,0,0,0,641,0,0,0,641,0,0);
INSERT IGNORE INTO tableUse VALUES ("%s",3,"trigger",21,0,20,1,0,0,1,486,0,0,0,47,0,0,0,47,0,0);
INSERT IGNORE INTO tableUse VALUES ("%s",3,"group",7,0,6,1,0,0,3,67,0,0,0,15,0,0,0,15,0,0);
INSERT IGNORE INTO tableUse VALUES ("%s",3,"user",4,0,3,1,0,1,0,0,0,0,0,16,0,0,0,16,0,0);
COMMIT;
BEGIN TRANSACTION;
""" % (md5, md5, md5, md5, md5, md5, md5, md5)
        if python3:
            md5 = "afafbfd330e2378418bfb4025a86617c"
            expected = """INSERT IGNORE INTO process VALUES ("%s",3,10664,"2016-10-19 12:01:08",NULL,NULL,NULL,"git-fusion-user","GF-TRIGGER-567d67de-962","10.100.104.199","p4/2016.1/NTX64/1396108","user-key","git-fusion-reviews-common-lock-owner",2,3,0,0,523588,523588,.000,.015,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,0,NULL);
UPDATE process SET uCpu=NULL,sCpu=NULL,diskIn=NULL,diskOut=NULL,ipcIn=NULL,ipcOut=NULL,maxRss=NULL,pageFaults=NULL,rpcMsgsIn=2,rpcMsgsOut=3,rpcSizeIn=0,rpcSizeOut=0,rpcHimarkFwd=523588,rpcHimarkRev=523588,rpcSnd=NULL,rpcRcv=NULL,error=NULL WHERE processKey = "%s" and lineNumber = 3;
UPDATE process SET endTime=startTime WHERE processKey = "%s" and lineNumber = 3 and endTime IS NULL;
INSERT IGNORE INTO tableUse VALUES ("%s",3,"user",4,0,3,1,0,1,0,0,0,0,0,16,0,0,0,16,0,0);
INSERT IGNORE INTO tableUse VALUES ("%s",3,"group",7,0,6,1,0,0,3,67,0,0,0,15,0,0,0,15,0,0);
INSERT IGNORE INTO tableUse VALUES ("%s",3,"protect",282,0,96,1,0,0,1,14495,0,0,0,641,0,0,0,641,0,0);
INSERT IGNORE INTO tableUse VALUES ("%s",3,"trigger",21,0,20,1,0,0,1,486,0,0,0,47,0,0,0,47,0,0);
INSERT IGNORE INTO tableUse VALUES ("%s",3,"nameval",6,4,4,0,1,0,0,0,1,0,0,0,16,15,0,0,16,15);
COMMIT;
BEGIN TRANSACTION;
""" % (md5, md5, md5, md5, md5, md5, md5, md5)
        saved_stdoutput = StringIO()
        log2sql = Log2sql(optionsText, instream=StringIO(input), outstream=saved_stdoutput)
        log2sql.processLog()
        actual = saved_stdoutput.getvalue()
        self.assertEqual(fileHeader, actual[:len(fileHeader)])
        # print("Expected:\n%s" % expected)
        # print("Actual:\n%s" % actual[len(fileHeader):])
        self.assertEqual(expected, actual[len(fileHeader):])

        # Test with SQL
        if os.path.exists(dbname):
            os.remove(dbname)
        log2sql = Log2sql(optionsSQL, instream=StringIO(input), outstream=saved_stdoutput)
        log2sql.processLog()
        conn = sqlite3.connect(dbname)
        c = conn.cursor()
        c.execute('SELECT * from Process;')
        rows = c.fetchall()
        self.assertEqual(len(rows), 1)
        row = rows[0]
        self.assertEqual(row[0], md5)
        self.assertEqual(row[3], '"2016-10-19 12:01:08"')
        self.assertEqual(row[4], '"2016-10-19 12:01:08"')
        conn.close()
        

        input = r"""
Perforce server info:
	2015/09/02 16:43:36 pid 4500 robert@robert-test 127.0.0.1 [Microsoft Visual Studio 2013/12.0.21005.1] 'user-reconcile -eadf -c 12253 c:\temp\robert-test\test\VEER!-%-#-@-$-&-(-)\fred - Copy.txt c:\temp\robert-test\test\VEER!-%-#-@-$-&-(-)\fred - Copy.txt c:\temp\robert-test\test\VEER!-%-#-@-$-&-(-)\fred - Copy.txt c:\temp\robert-test\test\VEER!-%-#-@-$-&-(-)\fred - Copy.txt'
Perforce server info:
	2015/09/02 16:43:36 pid 4500 completed .187s
Perforce server info:
	2015/09/02 16:43:36 pid 4500 robert@robert-test 127.0.0.1 [Microsoft Visual Studio 2013/12.0.21005.1] 'user-reconcile -eadf -c 12253 c:\temp\robert-test\test\VEER!-%-#-@-$-&-(-)\fred - Copy.txt c:\temp\robert-test\test\VEER!-%-#-@-$-&-(-)\fred - Copy.txt c:\temp\robert-test\test\VEER!-%-#-@-$-&-(-)\fred - Copy.txt c:\temp\robert-test\test\VEER!-%-#-@-$-&-(-)\fred - Copy.txt'
--- clients/robert-test(W)
---   total lock wait+held read/write 0ms+0ms/0ms+172ms
"""
        md5 = "fbf9c435752ee86fd40040d8aa0d4daf"
        if python3:
            md5 = "fbf9c435752ee86fd40040d8aa0d4daf"
        expected = """INSERT IGNORE INTO process VALUES ("%s",7,4500,"2015-09-02 16:43:36",NULL,NULL,NULL,"robert","robert-test","127.0.0.1","Microsoft Visual Studio 2013/12.0.21005.1","user-reconcile",
UPDATE process SET uCpu=NULL,sCpu=NULL,diskIn=NULL,diskOut=NULL,ipcIn=NULL,ipcOut=NULL,maxRss=NULL,pageFaults=NULL,rpcMsgsIn=NULL,rpcMsgsOut=NULL,rpcSizeIn=NULL,rpcSizeOut=NULL,rpcHimarkFwd=NULL,rpcHimarkRev=NULL,rpcSnd=NULL,rpcRcv=NULL,error=NULL WHERE processKey = "%s" and lineNumber = 7;
UPDATE process SET endTime=startTime WHERE processKey = "%s" and lineNumber = 7 and endTime IS NULL;
COMMIT;
BEGIN TRANSACTION;
""" % (md5, md5, md5)
        saved_stdoutput = StringIO()
        log2sql = Log2sql(optionsText, instream=StringIO(input), outstream=saved_stdoutput)
        log2sql.processLog()
        actual = saved_stdoutput.getvalue()
        self.assertEqual(fileHeader, actual[:len(fileHeader)])
        rest = actual[len(fileHeader):]
        for expline in expected.split("\n"):
            reLine = re.compile(expline.replace("(", "\("), re.MULTILINE)
            self.assertRegex(rest, reLine, re.MULTILINE)

        # Test with SQL
        dbname = "%s.db" % optionsSQL.dbname
        if os.path.exists(dbname):
            os.remove(dbname)
        log2sql = Log2sql(optionsSQL, instream=StringIO(input), outstream=saved_stdoutput)
        log2sql.processLog()
        conn = sqlite3.connect(dbname)
        c = conn.cursor()
        c.execute('SELECT * from Process;')
        rows = c.fetchall()
        self.assertEqual(len(rows), 1)
        row = rows[0]
        self.assertEqual(row[0], md5)
        self.assertEqual(row[3], '"2015-09-02 16:43:36"')
        self.assertEqual(row[4], '"2015-09-02 16:43:36"')
        conn.close()

if __name__ == '__main__':
    unittest.main()
# Change User Description Committed
#32 23632 Robert Cowham Placeholder to handle trigger output - not known about previously!
#31 23591 Robert Cowham Handle meta/db and similar records which may occur multiple times for a command with
vtrack output.
#30 23493 Robert Cowham Process peek track records
Process meta/client/change lock track records
Check for unrecognised track records (debug output if found)
#29 23446 Robert Cowham Duplicate pids for same command within same second now handled correctly!
#28 23445 Robert Cowham Fixed testChanges - if a cmd has track info then it is completed.
#27 23444 Robert Cowham Refactored tests
#26 23443 Robert Cowham Avoid processing cmds until time changes as this means out of order track
entries are processed appropriately.
(Normally a 'completed' is immediately followed by a track entry for the original
cmd - but sometimes the track entry comes a bit later after some other
unrelated cmds are logged. Previously this would lead to being treated as extra
cmds and ones which would never be completed. This in turn lead to lots of
performance loss in processCompletedCommands() function)
#25 23438 Robert Cowham Add some logging to track down performance issues
#24 23401 Robert Cowham Fix tests failing in python3 due to list re-ordering
#23 23399 Robert Cowham Handle utf encoding errors
#22 23375 Robert Cowham Show diffs better when tests fail
#21 23369 Robert Cowham Remove quotes around datetime in sqlite
#20 21829 Robert Cowham Fix problem with changes -o commands.
#19 21796 Robert Cowham Handle rmt-FileFetch records which may be duplicates as they don't have 'completed' entries.
#18 21712 Robert Cowham Check for correct line number when looking to update for track entries
#17 21708 Robert Cowham Tweak parameters to improve error messages.
Make output to stdout optional
#16 21705 Robert Cowham Minor refactoring for clarity.
Process all completed records as we go.
#15 21704 Robert Cowham A couple more tests for log formats.
#14 21703 Robert Cowham Fix failing python3 test
Add new test to ignore error blocks
#13 21702 Robert Cowham Rework algorithm to process blocks at a time, and to avoid the SQL update statements.
Risk of increased memory vs improved speed.
#12 21697 Robert Cowham Parse rcpSnd/rpcRcv and add to database.
#11 21696 Robert Cowham Test for client/locks entry
#10 21694 Robert Cowham Handle null values properly
#9 21660 Robert Cowham Handle utf8 in python2 strings
#8 21656 Robert Cowham Avoid SQL quoting issues with alternative insert statement.
#7 21643 Robert Cowham Handle git-fusion entries (strip the json) - for --sql option
#6 21402 Robert Cowham Filter out swarm commands
Test for db content in a basic fashion.
#5 21396 Robert Cowham Test for update rows.
#4 21393 Robert Cowham Add a swarm test - large record.
Improve performance by skipping easy matches early.
#3 21374 Robert Cowham Write to sqllite db
#2 21368 Robert Cowham Make tests work under python3
#1 21367 Robert Cowham Restructured for unit tests, and first unit tests.