traceservices/tracefw/ost_trace_api/unit_test/te_ost/src/te_multiparttrace.cpp
author Pat Downey <patd@symbian.org>
Wed, 01 Sep 2010 12:39:58 +0100
branchRCL_3
changeset 24 cc28652e0254
parent 23 26645d81f48d
permissions -rw-r--r--
Revert incorrect RCL_3 drop: Revision: 201035 Kit: 201035

// Copyright (c) 2007-2009 Nokia Corporation and/or its subsidiary(-ies).
// All rights reserved.
// This component and the accompanying materials are made available
// under the terms of "Eclipse Public License v1.0"
// which accompanies this distribution, and is available
// at the URL "http://www.eclipse.org/legal/epl-v10.html".
//
// Initial Contributors:
// Nokia Corporation - initial contribution.
//
// Contributors:
//
// Description:
//

#include <opensystemtrace.h>
#include <uloggerclient.h>
#include "te_multiparttrace.h"
#include "uloggerconfig.h"



//const data for testing purposes
const TTraceId KTestTraceId = 10245;
const TClassification KTestClassification = 254;
_LIT(KLogPath, "c:\\logs\\ulogger\\multitrace.utf");

//global variables
TInt fillPattern = 123;
TInt dataSize = 255;
TInt traceMethod = 0;
static const TComponentId KMyTestUid = 12345678;
TInt ordinal = 0;
TInt tarcerecords_expected = 0;


template<typename T>
T ReadTypeFromBuffer(const TUint8* aData, TInt& aOffset)
	{
	T p = *((T*)(aData+aOffset));
	aOffset += sizeof(T);
	return p;
	}


CCTe_multiparttrace::CCTe_multiparttrace()
	{
	SetTestStepName(KMultiTraceTestStep);
	}


CCTe_multiparttrace::~CCTe_multiparttrace()
	{
	}



TVerdict CCTe_multiparttrace::doTestStepPreambleL()
	{
	INFO_PRINTF1(_L("*** This test case is aimed to test multipart-traces ***"));

	//delete old trace log
	RFs fs;
	User::LeaveIfError( fs.Connect() );
	fs.Delete(KLogPath);

	// added this code  to ensure directories created on hardware
	TInt err = fs.MkDirAll(KLogPath);
	if( err != KErrNone && err != KErrAlreadyExists)
		{
		ERR_PRINTF2(_L("RFs::MkDirAll failed with error %d"), err);
		}


	fs.Close();



	//enable ULogger/Trace to log test traces
	INFO_PRINTF1(_L("INFO: configuring ULogger..."));
	User::LeaveIfError( iUlogger.Connect() );
	CClearConfig configIni;
	configIni.Clear(iUlogger);

	iUlogger.SetSecondaryFilteringEnabled(EFalse);

	_LIT8(KUloggerFilePlugin, "uloggerfileplugin");


	err = iUlogger.ActivateOutputPlugin(KUloggerFilePlugin);
	if( err != KErrNone && err != KErrAlreadyExists)
		{
		ERR_PRINTF2(_L("ActivateOutputPlugin failed with error %d"), err);
		User::LeaveIfError(err);
		}
	TPluginConfiguration pluginConf;
	pluginConf.SetKey(_L8("output_path"));
	pluginConf.SetValue(KLogPath);
	User::LeaveIfError( iUlogger.SetPluginConfigurations(KUloggerFilePlugin, pluginConf) );

	CArrayFixFlat<TUint8>* array = new (ELeave) CArrayFixFlat<TUint8>(4);
	CleanupStack::PushL(array);
	array->AppendL(KTestClassification);
	User::LeaveIfError( iUlogger.SetPrimaryFiltersEnabled(*array, ETrue));
	CleanupStack::PopAndDestroy(array);

	User::LeaveIfError( iUlogger.Restart());

	iUlogger.Close();

	return TestStepResult();
	}



TVerdict CCTe_multiparttrace::doTestStepL()
	{
	INFO_PRINTF1(_L("*** CCTe_multiparttrace::doTestStepL ***"));

	//generate trace data
	traceMethod = ETraceUsingTraceBig;
	TInt e = GenerateTraceDataL((CCTe_multiparttrace::TTraceMethod)traceMethod, dataSize, fillPattern);
	if(e != KErrNone)
		{
		INFO_PRINTF2(_L("ERROR: generating trace data failed (%d)"), e);
		SetTestStepResult(EFail);
		return TestStepResult();
		}


	//stop ulogger
	INFO_PRINTF1(_L("INFO: stopping ULogger..."));
	User::LeaveIfError( iUlogger.Connect() );
	User::LeaveIfError( iUlogger.Stop() );
	iUlogger.Close();

	return TestStepResult();
	}


TVerdict CCTe_multiparttrace::doTestStepPostambleL()
	{
	INFO_PRINTF1(_L("*** CCTe_multiparttrace::doTestStepPostambleL ***"));

	//validate the data that we just logged
	TInt e = KErrNone;
	if((e=CheckDataL((CCTe_multiparttrace::TTraceMethod)traceMethod, dataSize, fillPattern)) != KErrNone)
		{
		INFO_PRINTF2(_L("ERROR: checking data failed (%d)"), e);
		SetTestStepResult(EFail);
		}

	//delete log file
    RFs fs;
    User::LeaveIfError( fs.Connect() );
    fs.Delete(KLogPath);
	
	return TestStepResult();
	}


TInt CCTe_multiparttrace::GenerateTraceDataL(TTraceMethod aTraceMethod, TUint aMaxDataSize, TUint8 aFillPattern)
	{
	INFO_PRINTF4(_L("*** CCTe_multiparttrace::GenerateTraceDataL(%d, %d, %d) ***"), aTraceMethod, aMaxDataSize, aFillPattern);
	TInt e = KErrNone;

	INFO_PRINTF1(_L("INFO: generating trace data..."));
	TInt i,k;
	//generate and send data using desired Ost API
	TUint8* data = (TUint8*)User::Alloc(aMaxDataSize);
	for(i=0; i<aMaxDataSize; ++i)
		{
		//fill data with pattern provided
		for(k=0; k<i; ++k)
			data[k] = i-k;

		//send trace
		TBool loggedFlag=EFalse;
		if(aTraceMethod == ETraceUsingTraceBig)
			{
			loggedFlag = OstTrace(TTraceContext(KMyTestUid, KTestClassification), KTestTraceId, (const TAny*)data, i);
			//loggedFlag = BTraceContextBig(KTestClassification, 0, KMyTestUid, (const TAny*)data, i);
			}


		if(!loggedFlag)
			{
			INFO_PRINTF2(_L("ERROR: trace %d not logged!"), i);
			e = KErrGeneral;
			break;
			}
		}

	if(e==KErrNone)
	    {
		//INFO_PRINTF1(_L("INFO: data sent"));
	    }
	else
		INFO_PRINTF2(_L("ERROR: data sendiung failed (%d)"), e);

	//cleanup
	delete [] data;

	return e;
	}


TInt CCTe_multiparttrace::CheckDataL(TTraceMethod aTraceMethod, TUint aMaxDataSize, TUint8 aFillPattern)
	{
	INFO_PRINTF4(_L("*** CCTe_multiparttrace::CheckDataL(%d, %d, %d) ***"), aTraceMethod, aMaxDataSize, aFillPattern);

	INFO_PRINTF2(_L("INFO: opening log file... %S"), &(KLogPath()));
	RFs fs;
	RFile file;
	User::LeaveIfError( fs.Connect() );

	TInt err = file.Open(fs, KLogPath, EFileRead);
	if(err != KErrNone)
		{
		INFO_PRINTF3(_L("ERROR: opening log file error: err = %d filename=%S"), err, &(KLogPath()));
		return err;
		}

	//read trace log file
	TInt size = 0;
	file.Size(size);
	if(size > 0)
		{
		INFO_PRINTF2(_L("INFO: Trace Log file size: %d"), size);
		HBufC8* data = HBufC8::NewLC(size);
		TPtr8 p(data->Des());
		User::LeaveIfError( file.Read(p) );
		const TUint8* dataPtr = p.Ptr();
		err = ValidateTraceDataL(dataPtr, p.Length(), dataSize, fillPattern);
		CleanupStack::PopAndDestroy(data);
		}
	else{
		err = KErrGeneral;
		}

	//cleanup
	file.Close();
	fs.Close();

	return err;
	}


TInt CCTe_multiparttrace::ValidateTraceDataL(const TUint8* aDataPtr, TUint aDataSize, TUint aTraceRecords, TUint8 /*aFillPattern*/)
	{
	INFO_PRINTF1(_L("*** CCTe_multiparttrace::ValidateTraceDataL ***"));

	TUint8* tracePtr = (TUint8*)aDataPtr;
	TInt traceSize = aDataSize;

	TUint8 recSize=0, flags=0, category=0; //subCategory=0;
	TInt32 flags2=0;//, contextId=0, extra=0, timestamp2=0, pc=0;
	TBool missing = EFalse;
	TInt offset = 0;
	//TInt currentTraceSize=0;
	const TUint8* endPtr = tracePtr+traceSize;
	//parse trace data
	TInt traceRecordCounter=0;
	TInt testRecordCounter=0;

	while(tracePtr < endPtr)
		{
		User::After(100); 
		//INFO_PRINTF1(_L(" "));
		traceRecordCounter++;
		offset = 0;
		recSize = flags = flags2 /*= extra*/ = category /*= subCategory = contextId */= 0;
		missing = EFalse;

		//read trace header
		recSize = tracePtr[BTrace::ESizeIndex];
		flags = tracePtr[BTrace::EFlagsIndex];
		category = tracePtr[BTrace::ECategoryIndex];
		//subCategory = tracePtr[BTrace::ESubCategoryIndex];
		offset += 4;

			//read header extension
		if(flags & BTrace::EHeader2Present)
			flags2 = ReadTypeFromBuffer<TInt32>(tracePtr, offset);
		if(flags & BTrace::ETimestampPresent)
			ReadTypeFromBuffer<TInt32>(tracePtr, offset);
		if(flags & BTrace::ETimestamp2Present)
			/*timestamp2 =*/ ReadTypeFromBuffer<TInt32>(tracePtr, offset);
		if(flags & BTrace::EContextIdPresent)
			/*contextId =*/ ReadTypeFromBuffer<TInt32>(tracePtr, offset);
		if(flags & BTrace::EPcPresent)
			{
			/*pc = */ ReadTypeFromBuffer<TInt32>(tracePtr, offset);
			//INFO_PRINTF1(_L("INFO: PC present"));
			}
		if(flags & BTrace::EExtraPresent)
			{
			//extra = ETrue;
			ReadTypeFromBuffer<TInt32>(tracePtr, offset);
			//INFO_PRINTF1(_L("INFO: EXTRA present"));
			}


		if(flags & BTrace::ECpuIdMask)
			{
			//INFO_PRINTF1(_L("INFO: CPUID present"));
			}


		if(flags & BTrace::ERecordTruncated)
			{
			//trauncated = ETrue;
			}
		if(flags & BTrace::EMissingRecord)
			missing = ETrue;

		if(missing)
			{
			INFO_PRINTF1(_L("ERROR: ***** !!! MISSING TRACES ERROR !!! *****"));
			return KErrCorrupt; //indicates corrupted trace data
			}

		TInt _payloadSize = recSize-offset;
		//INFO_PRINTF2(_L("INFO: payloadSize = %d"), _payloadSize);

		//parse payload
		if(category == KTestClassification)
			{
			if(flags2 & BTrace::EMultipartFlagMask)
				{
//				TInt32 d1 = *(TUint32*)(tracePtr+offset); //total trace size
//				TInt32 d2 = *(TUint32*)(tracePtr+offset+4); //offset in collected data or UID
//				TUint8 d3 = *(TUint8*)(tracePtr+offset+8); //UID or random val
//				TUint8 d4_01 = *(TUint8*)(tracePtr+offset+12); //TraceId
//				TUint8 d4_02 = *(TUint8*)(tracePtr+offset+13); //reserved
//				TUint8 d5 = *(TUint8*)(tracePtr+offset+14); //TraceId

				//INFO_PRINTF7(_L("INFO: trace data: %d, %d, %d, %d, %d, %d)"), d1, d2, d3, d4_01, d4_02, d5);
				//INFO_PRINTF2(_L("INFO: trace number: %d"), testRecordCounter);

				//check TMultipart flag (and not CPU ID)
				switch(flags2 & BTrace::EMultipartFlagMask)
					{
					case BTrace::EMultipartFirst:
						{
						//TInt32 d1 = *(TUint32*) (tracePtr+offset); //extra size (Total trace size)
						//TInt32 d2 = *(TUint32*) (tracePtr+offset+4); //UID
						//TInt16 d3_01 = *(TUint16*) (tracePtr+offset+8); //TraceId
						//TInt16 d3_02 = *(TUint16*) (tracePtr+offset+10); //reserved
						//TUint8 d4 = *(TUint8*) (tracePtr+offset+12); //payload 1
						//INFO_PRINTF6(_L("FIRST TRACE: %d, %d, %d, %d, %d"), d1, d2, d3_01, d3_02, d4);

						//+4 is to mask TraceId and reserved value (2+2)
						if(ValidateTracePayloadL((const TUint8*)tracePtr+offset, _payloadSize, testRecordCounter, ETrue, testRecordCounter, ETrue, EFalse) != KErrNone)
							return KErrGeneral;
						} break;

					case BTrace::EMultipartMiddle:
						{
						TInt32 d1 = *(TUint32*)(tracePtr+offset); //extra size (Total trace size)
						TInt32 d2 = *(TUint32*)(tracePtr+offset+4); //current offset
						//TUint8 d3 = *(TUint8*)(tracePtr+offset+8); //payload 1
						//INFO_PRINTF4(_L("MIDDLE TRACE: %d, %d, %d"), d1, d2, d3);
						
						if(ValidateTracePayloadL((const TUint8*)tracePtr+offset, _payloadSize, testRecordCounter, ETrue, d1-d2, EFalse, EFalse) != KErrNone)
							return KErrGeneral;
						} break;

					case BTrace::EMultipartLast:
						{
						TInt32 d1 = *(TUint32*)(tracePtr+offset); //extra size (Total trace size)
						TInt32 d2 = *(TUint32*)(tracePtr+offset+4); //current offset
						//TUint8 d3 = *(TUint8*)(tracePtr+offset+8); //payload 1
						//INFO_PRINTF4(_L("LAST TRACE: %d, %d, %d"), d1, d2, d3);
						
						if(ValidateTracePayloadL((const TUint8*)tracePtr+offset, _payloadSize, testRecordCounter, ETrue, d1-d2, EFalse, ETrue) != KErrNone)
							return KErrGeneral;

						testRecordCounter++;
						} break;

					default:
						{
						INFO_PRINTF1(_L("ERROR: wrong value of flags2"));
						return KErrGeneral;
						}//break;
					}


				}
			else //not multiparted trace
				{
				if(ValidateTracePayloadL((const TUint8*)tracePtr+offset, _payloadSize, testRecordCounter, EFalse, testRecordCounter, ETrue, ETrue) != KErrNone)
					return KErrGeneral;
				testRecordCounter++;
				}
			}

		tracePtr = BTrace::NextRecord((TAny*)tracePtr);
		}

	INFO_PRINTF2(_L("INFO: %d trace records parsed"), traceRecordCounter);
	INFO_PRINTF2(_L("INFO: %d test trace records parsed"), testRecordCounter);
	if(testRecordCounter != aTraceRecords)
		{
		INFO_PRINTF3(_L("ERROR: wrong number of trace records with desired category (%d vs %d)"), testRecordCounter, aTraceRecords);
		return KErrGeneral;
		}

	return KErrNone;
	}


TInt CCTe_multiparttrace::ValidateTracePayloadL(const TUint8* aDataPtr, TUint aDataSize, TInt aTotalTraceSize, TBool aMultiPart, TUint8 aExpectedFirstVal, TBool aFirstTrace, TBool aLastTrace)
	{
	TInt offset = 0;

	//check some metadata that is stored in payload
	if(aFirstTrace)
		{
		ordinal = 0;

		if(aMultiPart)
			{
			TUint totalTraceSize = (TUint32) *(TUint32*)((TUint8*)aDataPtr+offset);
			offset+=4;
			if(totalTraceSize != aExpectedFirstVal)
				{
				INFO_PRINTF3(_L("ERROR: wrong totalTraceSize value (%d vs %d)"), totalTraceSize, aExpectedFirstVal);
				return KErrGeneral;
				}
			}

		TUint32 uid = (TUint32) *(TUint32*)((TUint8*)aDataPtr+offset);
		offset += 4;
		if(uid != KMyTestUid)
			{
			INFO_PRINTF3(_L("ERROR: wrong uid value (%d vs %d)"), uid, KMyTestUid);
			return KErrGeneral;
			}


		//read and test Ost TraceId
		TUint16 traceId = (TUint16) *(TUint16*)((TUint8*)aDataPtr+offset);
		if(traceId != KTestTraceId)
			{
			INFO_PRINTF3(_L("ERROR: wrong traceId value (%d vs %d)"), traceId, KTestTraceId);
			return KErrGeneral;
			}
		offset += 2;

		//read reserved value (not used by Ost at the moment)
		//TUint16 unused = (TUint16) *(TUint16*)((TUint8*)aDataPtr+offset);
		offset += 2;
		}
	else if(aMultiPart)
		{
		//non-first multipart trace
		TUint totalTraceSize = (TUint32) *(TUint32*)((TUint8*)aDataPtr+offset);
		offset+=4;

		if(totalTraceSize != aTotalTraceSize)
			{
			INFO_PRINTF3(_L("ERROR: wrong totalTraceSize (in MIDDLE or LAST multipart trace) value (%d vs %d)"), totalTraceSize, aTotalTraceSize);
			return KErrGeneral;
			}

		//TUint32 tracerDataOffset = tracerDataOffset = (TUint32) *(TUint32*)((TUint8*)aDataPtr+offset);
		offset+=4;

		}

	//validate content of the trace data
	TInt expectedVal = aExpectedFirstVal;
	TBool reallyFirstRecord = aFirstTrace;
	while (offset < aDataSize)
		{
		TUint8 d = *((TUint8*)aDataPtr+offset);
		++ordinal;

		if(reallyFirstRecord)
			{
			tarcerecords_expected = d;
			reallyFirstRecord = EFalse;
			}

		if (d != expectedVal)
			{
			INFO_PRINTF3(_L("ERROR: wrong data value (%d vs %d)"), d, expectedVal);
			return KErrGeneral;
			}
		++offset;
		--expectedVal;
		}

	if(offset != aDataSize)
		{
		INFO_PRINTF3(_L("ERROR: wrong payload size (%d vs %d)"), offset, aDataSize);
		return KErrGeneral;
		}

	if(aLastTrace && tarcerecords_expected != ordinal)
		{
		INFO_PRINTF3(_L("ERROR: wrong number of traces (%d vs %d)"), tarcerecords_expected, ordinal);
		return KErrGeneral;
		}

	//INFO_PRINTF1(_L("INFO: trace data checked"));
	return KErrNone;
	}