# -*- 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, 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 testBasicParsing(self): "simple parsing" optionsText = MyOptions("testdb", "") optionsSQL = MyOptions("testdb", "", sql=True) dbname = "%s.db" % optionsSQL.dbname # New client/lock info # 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 .000s/.000s # --- 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 # 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,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,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,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() # 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,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() # 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,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() # 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,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,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,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,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,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()