#include <windows.h>
#include <pkfuncs.h>
#include <kernel.h>

// see
// c:/Program Files/Windows Mobile 6 SDK/PocketPC/Include/Armv4i/devload.h
#include <set>

#include "stringutils.h"

#define BINLOGBUFFERSIZE 0x100000
#define TIMESTAMP_INTERVAL 10000

// 2 ways of connecting to the old device:
//    - DONE: via normal dev interface
//    - DONE: loaded as dll

// done: make attach unique id to each log entry, to make it easier to group them together in the log
// done: register as 'naked' device, to make it easier to add it as any kind of device.
// todo: added special ioctl, which saves/flushes all logs to disk
// todo: add 'merged' log option.
// todo: improve stream-logfile naming

/*
# rdo1 -> logdev
#      target=rdo2
# rdo2 -> radio
installdev: ../build/logdev.dll
	pput -f ../build/logdev.dll "%CSIDL_WINDOWS%"
	pregutl -c HKLM\\Drivers\\BuiltIn\\Thunkdev
	pregutl -s HKLM\\Drivers\\BuiltIn\\Thunkdev :Dll=sz:radio.dll :Index=dword:00000002 :Order=dword:00000002 :Prefix=sz:RDO :Priority256=dword:00000093
	pregutl -s HKLM\\Drivers\\BuiltIn\\QRADIO :Dll=sz:logdev.dll :target=sz:RDO2:

[HKLM\drivers\active\15]
BusName="BuiltInPhase1_0_1_0"
BusParent=dword:000323d0
Hnd=dword:0003d6c0
InterfaceType=dword:00000000
Key="Drivers\BuiltIn\Thunkdev"
Name="RDO2:"

[HKLM\Drivers\BuiltIn\Thunkdev]
Dll="radio.dll"
Index=dword:00000002
Order=dword:00000002
Prefix="RDO"
Priority256=dword:00000093

*/

// performance:
//
// (verbose=4,  target=drivers\builtin\thunkdev)
// c3800000 01800000 01800000 c3805000 00000008 virser_data.dll
// 6f1b2d32 01802cf0 95 95 8c095880 8c095880 08a4fe20   0.0   8.2                 afa17df2: device.exe 20
// c3880000 01880000 01880000 c3891000 00000008 radio.dll
// 8f937fca 01887e2c 5f 5f 8c095880 8c095880 083dfe1c   0.0   5.4                 afa17df2: device.exe 20
// ef910a4e 01887fac 67 67 8c095880 8c095880 0840fdf0   0.0   1.0                 afa17df2: device.exe 20
// c3940000 01940000 01940000 c394e000 00000008 wavedev.dll
// af826882 01947d2c 63 63 8c095880 8c095880 0859fe1c   0.0   5.5                 afa17df2: device.exe 20

// no logging device:
// c3800000 01800000 01800000 c3805000 00000008 virser_data.dll
// 2f02efa2 01802cf0 95 95 8c095880 8c095880 08a8fe20   0.0   0.6                 efa16df2: device.exe 20
// c3880000 01880000 01880000 c3891000 00000008 radio.dll
// 0f946fca 01887e2c 5f 5f 8c095880 8c095880 083bfe1c   0.0   2.8                 efa16df2: device.exe 20
// 0f926e62 01887fac 67 67 8c095880 8c095880 0840fdf0   0.0   0.8                 efa16df2: device.exe 20
// c3940000 01940000 01940000 c394e000 00000008 wavedev.dll
// 0f8399f6 01947d2c 63 63 8c095880 8c095880 0859fe1c   0.0   5.5                 efa16df2: device.exe 20

// (verbose=4, target=RDO2)
// c3800000 01800000 01800000 c3805000 00000008 virser_data.dll
// 8f3d72ae 01802cf0 95 95 8c095880 8c095880 08a3fe20   0.0   8.4                 afa1adf2: device.exe 20
// c3880000 01880000 01880000 c3891000 00000008 radio.dll
// 8f9618ba 01887e2c 5f 5f 8c095880 8c095880 0835fe1c   0.0   5.2                 afa1adf2: device.exe 20
// 6f92ae62 01887fac 67 67 8c095880 8c095880 0840fdf0   0.0   1.0                 afa1adf2: device.exe 20
// c3940000 01940000 01940000 c394e000 00000008 wavedev.dll
// cf83dab2 01947d2c 63 63 8c096188 8c096188 0859fe44   0.0   6.0                 afa1adf2: device.exe 20


// (verbose=0x14,  target=drivers\builtin\thunkdev)
// c3800000 01800000 01800000 c3805000 00000008 virser_data.dll
// 6e4a3f8a 01802cf0 95 95 8c095880 8c095880 0921fe20   0.0   2.5                 afa1adf2: device.exe 20
// c3880000 01880000 01880000 c3891000 00000008 radio.dll
// cf93bd3a 01887e2c 5f 5f 8c095880 8c095880 083cfe1c   0.0   5.3                 afa1adf2: device.exe 20
// 4f914936 01887fac 67 67 8c095880 8c095880 0840fdf0   0.0   0.8                 afa1adf2: device.exe 20
// c3940000 01940000 01940000 c394e000 00000008 wavedev.dll
// cf728576 01947d2c 63 63 8c095880 8c095880 086afe1c   0.0   5.8                 afa1adf2: device.exe 20

// (verbose=0x14,  target=drivers\builtin\thunkdev)
// c3800000 01800000 01800000 c3805000 00000008 virser_data.dll
// ceba1152 01802cf0 95 95 8c095880 8c095880 091efe20   0.0   0.8                 afa18df2: device.exe 20
// c3880000 01880000 01880000 c3891000 00000008 radio.dll
// ef933f22 01887e2c 5f 5f 8c095880 8c095880 083cfe1c   0.0   3.0                 afa18df2: device.exe 20
// 2f912936 01887fac 67 67 8c095880 8c095880 0840fdf0   0.0   0.8                 afa18df2: device.exe 20
// c3940000 01940000 01940000 c394e000 00000008 wavedev.dll
// 0f7255ba 01947d2c 63 63 8c095880 8c095880 086afe1c   0.0   5.6                 afa18df2: device.exe 20
//
// some notes:
//    Read's are usually from a reader-thread in virser_atcmd.dll or virser_data.dll
//    Write's are directly from threads in spcore or rilgsm
//
//-------------------------------------------------------------------
#define EXPORT __declspec(dllexport) 
extern "C" {
EXPORT DWORD Init( DWORD dwContext);
EXPORT BOOL Close( DWORD Handle);
EXPORT BOOL Deinit( DWORD dwContext);
EXPORT DWORD Open( DWORD dwData, DWORD dwAccess, DWORD dwShareMode);
EXPORT BOOL IOControl( DWORD Handle, DWORD dwIoControlCode, PBYTE pInBuf, DWORD nInBufSize, PBYTE pOutBuf, DWORD nOutBufSize, PDWORD pBytesReturned);
EXPORT DWORD Read(DWORD Handle, LPVOID pBuffer, DWORD dwNumBytes);
EXPORT DWORD Write(DWORD Handle, LPCVOID pBuffer, DWORD dwNumBytes);
EXPORT DWORD Seek(DWORD Handle, long lDistance, DWORD dwMoveMethod);
EXPORT void PowerUp(void);
EXPORT void PowerDown(void);
}

typedef DWORD (*PFNInit)( DWORD dwContext);
typedef BOOL (*PFNClose)( DWORD Handle);
typedef BOOL (*PFNDeinit)( DWORD dwContext);
typedef DWORD (*PFNOpen)( DWORD dwData, DWORD dwAccess, DWORD dwShareMode);
typedef BOOL (*PFNIOControl)( DWORD Handle, DWORD dwIoControlCode, PBYTE pInBuf, DWORD nInBufSize, PBYTE pOutBuf, DWORD nOutBufSize, PDWORD pBytesReturned);
typedef DWORD (*PFNRead)(DWORD Handle, LPVOID pBuffer, DWORD dwNumBytes);
typedef DWORD (*PFNWrite)(DWORD Handle, LPCVOID pBuffer, DWORD dwNumBytes);
typedef DWORD (*PFNSeek)(DWORD Handle, long lDistance, DWORD dwMoveMethod);
typedef void (*PFNPowerUp)(void);
typedef void (*PFNPowerDown)(void);

PFNInit      DrvInit;
PFNClose     DrvClose;
PFNDeinit    DrvDeinit;
PFNOpen      DrvOpen;
PFNIOControl DrvIOControl;
PFNRead      DrvRead;
PFNWrite     DrvWrite;
PFNSeek      DrvSeek;
PFNPowerUp   DrvPowerUp;
PFNPowerDown DrvPowerDown;



//-------------------------------------------------------------------

#define VERBOSE_IOCONTROL 1
#define VERBOSE_READWRITE 2
#define VERBOSE_BINARY 4
#define VERBOSE_FLUSHOFTEN 8     // buffers are flushed to disk either every write, or every 64 writes
#define VERBOSE_MEMBUFFER 0x10
#define VERBOSE_THREADINFO 0x20
// 1 : log iocontrol
// 2 : log read/write
// 4 : log binary
// 8 : flush every write
//10 : log to memorybuffer
//20 : log thread info
static DWORD verbose;

HANDLE hLog;
int nlogs;
void openlog()
{
    if (hLog!=NULL && hLog!=INVALID_HANDLE_VALUE)
        return;
    hLog= CreateFile(_T("\\logdev.log"), GENERIC_WRITE, FILE_SHARE_READ, NULL, OPEN_ALWAYS, 0, NULL); 
    if (hLog==INVALID_HANDLE_VALUE) {
        hLog= NULL;
        OutputDebugString(_T("error opening logdev.log\n"));
    }
}
void closelog()
{
    CloseHandle(hLog);
    hLog=NULL;
}
void writelog(char *data, int size)
{
    DWORD nWritten;
    WriteFile(hLog, data, size, &nWritten, 0);

    if ( ((verbose&VERBOSE_FLUSHOFTEN)!=0) || (((++nlogs)&0x3f)==0) )
        FlushFileBuffers(hLog);
}
void log(char *msg, ...)
{
    va_list ap;
    char buf[1024];

    va_start(ap, msg);
	int n= _vsnprintf(buf, 1024, msg, ap);
    buf[1024]=0;
    va_end(ap);

    writelog(buf, n);
}
int hexchar(BYTE c)
{
    return '0'+c+(c>9?7:0);
}
int hexdata(char *line, BYTE *buf, int size)
{
    for (int i=0 ; i<16 ; i++) {
        line[i*3]=' ';
        if (i<size) {
            line[i*3+1]=hexchar(buf[i]>>4);
            line[i*3+2]=hexchar(buf[i]&0xf);
        }
        else {
            line[i*3+1]=' ';
            line[i*3+2]=' ';
        }
    }
    line[48]=0;
    return 48;
}
int ascdata(char *line, BYTE *buf, int size)
{
    for (int i=0 ; i<16 ; i++) {
        if (i<size)
            line[i]=((buf[i]<32)||(buf[i]>0x7e)) ? '.' : buf[i];
        else
            line[i]=' ';
    }
    line[16]=0;
    return 16;
}
void hexdump(DWORD t, char *tag, BYTE *buf, int size)
{
    char line[128];
    for (int ofs=0 ; ofs<size ; ofs+=16) {
        int i= _snprintf(line, 128, "%08lx-%.8s %04x:", t, tag, ofs);

        i+=hexdata(line+i, buf+ofs, size-ofs);
        line[i++]=' ';
        line[i++]=' ';
        i+=ascdata(line+i, buf+ofs, size-ofs);
        line[i++]='\n';
        writelog(line, i);
    }
}
//-------------------------------------------------------------------
//typedef std::map<DWORD,struct threadinfo*> ThreadMap;
//ThreadMap threadmap;
typedef std::set<DWORD> ThreadSet;
ThreadSet threadset;

HDATA *cvHandle2HDataPtr(HANDLE h)
{
    return (HDATA *)(KData.handleBase+((DWORD)h&HANDLE_ADDRESS_MASK));
}
std::string dumpprocinfo(PROCESS*p)
{
    return stringformat("proc{%08lx  '%ls' %ls}", p->hProc, p->lpszProcName, p->pcmdline);
}
std::string dumpcallstack(CALLSTACK *p)
{
    return stringformat("cs{ret=%08lx sp=%08lx %s}", p->retAddr, p->dwPrevSP, dumpprocinfo(p->pprcLast).c_str());
}
void dumpthreadinfo(DWORD tid)
{
    if ((verbose&VERBOSE_THREADINFO)==0)
        return;
    if (threadset.find(tid)!=threadset.end())
        return;
    threadset.insert(tid);
	HDATA *pHandle= cvHandle2HDataPtr((HANDLE)tid);

	THREAD *thrd= (THREAD*)pHandle->pvObj;

    log("threadinfo %08lx->%08lx, cur=%s owner=%s\n", tid, thrd, dumpprocinfo(thrd->pProc).c_str(), dumpprocinfo(thrd->pOwnerProc).c_str());

    log("thread-callstack: ");
    for (struct CALLSTACK *ps = thrd->pcstkTop ; ps ; ps= ps->pcstkNext)
        log("%s", dumpcallstack(ps).c_str());
    log("\n");
}

//-------------------------------------------------------------------
BOOL ReadRegistryString(HKEY hRoot, LPTSTR devicekey, LPTSTR valname, TCHAR *strval, int maxlen)
{
    HKEY hDevkey;
    BOOL result= TRUE;
    LONG rc;
    if (devicekey) {
        rc= RegOpenKeyEx(hRoot, devicekey, 0, 0, &hDevkey);
        if (rc) {
            log("RegOpenKeyEx(%ls): ERROR %08lx\n", devicekey, rc);
            return FALSE;
        }
    }
    else {
        hDevkey= hRoot;
    }

    DWORD valtype=0;
    DWORD maxsize= sizeof(TCHAR)*(maxlen-1);
    rc= RegQueryValueEx(hDevkey, valname, NULL, &valtype, (LPBYTE)strval, &maxsize);
    if (rc) {
        log("RegQueryValueEx('%ls', '%ls', string(%d)): ERROR %08lx\n", devicekey, valname, maxlen, rc);
        result= FALSE;
    }
    else {
        strval[maxlen-1]=0;
    }
    if (devicekey)
        RegCloseKey(hDevkey);
    return result;
}
BOOL ReadRegistryDword(HKEY hRoot, LPTSTR devicekey, LPTSTR valname, DWORD *pvalue)
{
    HKEY hDevkey;
    BOOL result= TRUE;
    LONG rc;
    if (devicekey) {
        rc= RegOpenKeyEx(hRoot, devicekey, 0, 0, &hDevkey);
        if (rc) {
            log("RegOpenKeyEx(%ls): ERROR %08lx\n", devicekey, rc);
            return FALSE;
        }
    }
    else {
        hDevkey= hRoot;
    }

    DWORD valtype=0;
    DWORD maxsize= sizeof(DWORD);
    rc= RegQueryValueEx(hDevkey, valname, NULL, &valtype, (LPBYTE)pvalue, &maxsize);
    if (rc) {
        log("RegQueryValueEx('%ls', '%ls', DWORD): ERROR %08lx\n", devicekey, valname, rc);
        result= FALSE;
    }
    if (devicekey)
        RegCloseKey(hDevkey);
    return result;
}
//-------------------------------------------------------------------
//
// targetdev is either a devicename ( like 'RDO2:' )
// or a devicekey ( like 'Drivers\BuiltIn\QRADIO' )
static TCHAR targetdev[MAX_PATH];
static TCHAR devkey[MAX_PATH];

// data from loaded driver
static HINSTANCE hLib;
static DWORD dwDriver;
//-------------------------------------------------------------------
BOOL APIENTRY DllMain( HANDLE hModule,
                       DWORD  ul_reason_for_call,
                       LPVOID lpReserved
                     )
{
    if (ul_reason_for_call==DLL_PROCESS_ATTACH) {
        openlog();
        log("%08lx: dllmain hm=%08lx ul=%08lx lp=%08lx\n", GetCurrentThreadId(), hModule, ul_reason_for_call, lpReserved);
    }
    else if (ul_reason_for_call==DLL_PROCESS_DETACH) {
        closelog();
    }
    dumpthreadinfo(GetCurrentThreadId());
    return TRUE;
}
//-------------------------------------------------------------------
bool LoadDriver(TCHAR *drvkey)
{
    TCHAR drvdll[MAX_PATH];
    if (!ReadRegistryString(HKEY_LOCAL_MACHINE, drvkey, _T("Dll"), drvdll, MAX_PATH))
        goto errorexit;

    TCHAR prefix[MAX_PATH];
    if (!ReadRegistryString(HKEY_LOCAL_MACHINE, drvkey, _T("Prefix"), prefix, MAX_PATH))
        goto errorexit;

    DWORD dwFlags=0;
    ReadRegistryDword(HKEY_LOCAL_MACHINE, drvkey, _T("Flags"), &dwFlags);

    log("LoadDriver(%ls), drvdll=%ls   prefix=%ls\n", drvkey, drvdll, prefix);
    hLib= LoadLibrary(drvdll);
    if (hLib==NULL || hLib==INVALID_HANDLE_VALUE) {
        log("LoadLibrary(%ls) : ERROR %08lx", drvdll, GetLastError());
        goto errorexit;
    }
    log("driver dll loaded: %08lx\n", hLib);

// loads device functions prefixed with the device name
#define LOADPREFIXPROC(n) \
    Drv##n = (PFN##n)GetProcAddress(hLib, ToWString(stringformat("%ls_" #n, prefix)).c_str()); \
    if (Drv##n==NULL) { \
        log("GetProcAddr(%ls) : ERROR %08lx", ToWString(stringformat("%ls_" #n, prefix)).c_str(), GetLastError()); \
        goto errorexit_unloadlib; \
    }

// loads 'naked' device functions
#define LOADNOPREFIXPROC(n) \
    Drv##n = (PFN##n)GetProcAddress(hLib, _T(#n)); \
    if (Drv##n==NULL) { \
        log("GetProcAddr(%ls) : ERROR %08lx", _T(#n), GetLastError()); \
        goto errorexit_unloadlib; \
    }
#ifndef DEVFLAGS_NAKEDENTRIES
#define DEVFLAGS_NAKEDENTRIES 8
#endif
    if (dwFlags&DEVFLAGS_NAKEDENTRIES) {
        LOADNOPREFIXPROC(Init)
        LOADNOPREFIXPROC(Close)
        LOADNOPREFIXPROC(Deinit)
        LOADNOPREFIXPROC(Open)
        LOADNOPREFIXPROC(IOControl)
        LOADNOPREFIXPROC(Read)
        LOADNOPREFIXPROC(Write)
        LOADNOPREFIXPROC(Seek)
        LOADNOPREFIXPROC(PowerUp)
        LOADNOPREFIXPROC(PowerDown)
    }
    else {
        LOADPREFIXPROC(Init)
        LOADPREFIXPROC(Close)
        LOADPREFIXPROC(Deinit)
        LOADPREFIXPROC(Open)
        LOADPREFIXPROC(IOControl)
        LOADPREFIXPROC(Read)
        LOADPREFIXPROC(Write)
        LOADPREFIXPROC(Seek)
        LOADPREFIXPROC(PowerUp)
        LOADPREFIXPROC(PowerDown)
    }

    if (!(DrvInit && DrvClose && DrvDeinit && DrvOpen && DrvIOControl && DrvRead && DrvWrite && DrvSeek && DrvPowerUp && DrvPowerDown)) {
        log("not all driver functions loaded: DrvInit=%08lx DrvClose=%08lx DrvDeinit=%08lx DrvOpen=%08lx DrvIOControl=%08lx DrvRead=%08lx DrvWrite=%08lx DrvSeek=%08lx DrvPowerUp=%08lx DrvPowerDown\n", DrvInit,  DrvClose,  DrvDeinit,  DrvOpen,  DrvIOControl,  DrvRead,  DrvWrite,  DrvSeek,  DrvPowerUp,  DrvPowerDown);
        goto errorexit_unloadlib;
    }
    return true;

errorexit_unloadlib:
    FreeLibrary(hLib);
errorexit:
    hLib= NULL;
    return false;
}
//-------------------------------------------------------------------
#define MYMAGIC 0x98761234

#define MAX_HANDLES 256
struct handle_info {
    DWORD dwMagic;
    union {
    HANDLE hTarget;
    DWORD dwTarget;
    };
    DWORD idx;
    HANDLE hLog;
    CRITICAL_SECTION lock;
    BYTE *buffer;
    BYTE *bufptr;
    BYTE *bufend;
    DWORD tLastTimestamp;
};
struct handle_info *handles[MAX_HANDLES];
BOOL CheckHandle(const char *fn,struct handle_info *hi)
{
    if (hi->dwMagic!=MYMAGIC || handles[hi->idx]!=hi) {
        log("%08lx %s: ERROR %08lx not a valid handle: magic=%08lx, idx=%d list:%08lx\n", 
                GetCurrentThreadId(),
                fn, hi, hi->dwMagic, hi->idx, (hi->idx<MAX_HANDLES)?handles[hi->idx]:0);
        SetLastError(ERROR_INVALID_HANDLE);
        return FALSE;
    }
    return TRUE;
}
void openbinlog(struct handle_info *hi)
{
    InitializeCriticalSection(&(hi->lock));
    EnterCriticalSection(&(hi->lock));
    hi->hLog= CreateFile(ToWString(stringformat("\\log-%08lx.log", hi->hTarget)).c_str(), GENERIC_WRITE, FILE_SHARE_READ, NULL, OPEN_ALWAYS, 0, NULL); 
    if (hi->hLog==INVALID_HANDLE_VALUE) {
        hi->hLog= NULL;
        LeaveCriticalSection(&(hi->lock));
        return;
    }
    if (verbose&VERBOSE_MEMBUFFER) {
        hi->buffer= (BYTE*)LocalAlloc(LMEM_FIXED, BINLOGBUFFERSIZE);
        hi->bufptr= hi->buffer;
        if (hi->buffer) {
            hi->bufend= hi->buffer+ BINLOGBUFFERSIZE;
        }
        else {
            hi->bufend= NULL;
        }
    }
    LeaveCriticalSection(&(hi->lock));
}
void closebinlog(struct handle_info *hi)
{
    EnterCriticalSection(&(hi->lock));
    if ((verbose&VERBOSE_MEMBUFFER)!=0 && hi->buffer) {
        DWORD n;
        WriteFile(hi->hLog, hi->buffer, hi->bufptr-hi->buffer, &n, 0);
        hi->bufptr= hi->buffer;
    }
    if (hi->hLog!=NULL && hi->hLog!=INVALID_HANDLE_VALUE)
        CloseHandle(hi->hLog);
    hi->hLog= NULL;
    LeaveCriticalSection(&(hi->lock));
    DeleteCriticalSection(&(hi->lock));
}
void flushbinlog(struct handle_info *hi)
{
    EnterCriticalSection(&(hi->lock));
    if ((verbose&VERBOSE_MEMBUFFER)!=0 && hi->buffer) {
        DWORD n;
        WriteFile(hi->hLog, hi->buffer, hi->bufptr-hi->buffer, &n, 0);
        hi->bufptr= hi->buffer;
    }
    FlushFileBuffers(hi->hLog);
    LeaveCriticalSection(&(hi->lock));
}

#define LOGTYPE_WRITE  0
#define LOGTYPE_READ   1
#define LOGTYPE_STAMP  2
void binarylog(struct handle_info *hi, DWORD tick, DWORD type, BYTE *data, DWORD size);
void logtimestamp(struct handle_info *hi)
{
    SYSTEMTIME st;
    DWORD t= GetTickCount();
    if (t-hi->tLastTimestamp < TIMESTAMP_INTERVAL)
        return;
    GetSystemTime(&st);
    binarylog(hi, t, LOGTYPE_STAMP, (BYTE*)&st, sizeof(st));
    hi->tLastTimestamp= t;
}
void binarylog(struct handle_info *hi, DWORD tick, DWORD type, BYTE *data, DWORD size)
{
    DWORD n;
    if (hi->hLog==NULL)
        return;
    EnterCriticalSection(&(hi->lock));
    if ((verbose&VERBOSE_MEMBUFFER)!=0 && hi->buffer) {
        if (hi->bufptr+12+size<hi->bufend) {
            memcpy(hi->bufptr, &tick, sizeof(DWORD));
            hi->bufptr+=sizeof(DWORD);
            memcpy(hi->bufptr, &type, sizeof(DWORD));
            hi->bufptr+=sizeof(DWORD);
            memcpy(hi->bufptr, &size, sizeof(DWORD));
            hi->bufptr+=sizeof(DWORD);
            memcpy(hi->bufptr, data, size);
            hi->bufptr+=size;
        }
        // todo: log note that we stopped logging due to buffer full
    }
    else {
        WriteFile(hi->hLog, (BYTE*)&tick, sizeof(DWORD), &n, 0);
        WriteFile(hi->hLog, (BYTE*)&type, sizeof(DWORD), &n, 0);
        WriteFile(hi->hLog, (BYTE*)&size, sizeof(DWORD), &n, 0);
        WriteFile(hi->hLog, data, size, &n, 0);
    }
    LeaveCriticalSection(&(hi->lock));
    if (type!=LOGTYPE_STAMP)
        logtimestamp(hi);
}

//-------------------------------------------------------------------
DWORD Init( DWORD dwContext)
{
    // todo: change this to:
    // HKEY hDevkey= OpenDeviceKey(dwContext);
    // ReadRegistryString(hDevkey, NULL, _T("target"), targetdev, MAX_PATH)
    if (!ReadRegistryString(HKEY_LOCAL_MACHINE, (LPTSTR)dwContext, _T("Key"), devkey, MAX_PATH)) {
        log("%08lx Init: ERROR getting target device key from %ls\n", GetCurrentThreadId(), dwContext);
        return NULL;
    }
    if (!ReadRegistryString(HKEY_LOCAL_MACHINE, devkey, _T("target"), targetdev, MAX_PATH)) {
        log("%08lx Init: ERROR getting target device name\n", GetCurrentThreadId());
        return NULL;
    }
    if (!ReadRegistryDword(HKEY_LOCAL_MACHINE, devkey, _T("verbose"), &verbose))
        verbose=0;

    if (_tcschr(targetdev, '\\')==NULL && targetdev[_tcslen(targetdev)-1]==':') {
        // is devicename ->handled by Open
        log("%08lx %08lx: Init(%ls): OK dev=%ls\n", GetCurrentThreadId(), GetTickCount(), dwContext, targetdev);
        dumpthreadinfo(GetCurrentThreadId());
        return 1;
    }
    else {
        if (!LoadDriver(targetdev)) {
            log("%08lx Init(%ls): failed to load driver\n", GetCurrentThreadId(), dwContext);
            return NULL;
        }
        // TODO: create a new context for the new driver.
        dwDriver= DrvInit(dwContext);
        log("%08lx %08lx: Init(%ls): OK driver=%08lx\n", GetCurrentThreadId(), GetTickCount(), dwContext, dwDriver);
        return dwDriver;
    }
}


BOOL Close( DWORD Handle)
{
    struct handle_info *hi= (struct handle_info *)Handle;
    if (!CheckHandle("Close", hi))
        return FALSE;

    DWORD t0, t1;
    DWORD stat=ERROR_INVALID_HANDLE;
    BOOL rc=FALSE;
    if (hi->hTarget!=NULL && hi->hTarget!=INVALID_HANDLE_VALUE) {
        SetLastError(0);
        t0= GetTickCount();
        if (hLib)
            rc= DrvClose(hi->dwTarget);
        else
            rc= CloseHandle(hi->hTarget);
        stat=GetLastError();
        t1= GetTickCount();

        log("%08lx %08lx-%08lx Close(%08lx:%08lx) -> %08lx (stat=%08lx)\n", GetCurrentThreadId(), t0, t1, hi, hi->hTarget, rc, stat);
    }
    else {
        log("%08lx Close: ERROR handle not open: %08lx:%08lx\n", GetCurrentThreadId(), hi, hi->hTarget);
    }
    if (verbose&VERBOSE_BINARY)
        closebinlog(hi);

    handles[hi->idx]=NULL;
    LocalFree(hi);
    SetLastError(stat);
    return rc;
}
BOOL Deinit( DWORD dwContext)
{
    for(int i=0 ; i<MAX_HANDLES ; i++)
        if (handles[i])
            Close((DWORD)handles[i]);
    log("%08lx %08lx: Deinit(%08lx)\n", GetCurrentThreadId(), GetTickCount(), dwContext);
    if (hLib) {
        DrvDeinit(dwDriver);
        FreeLibrary(hLib);
        hLib= NULL;
    }
    return TRUE;
}
DWORD Open( DWORD dwData, DWORD dwAccess, DWORD dwShareMode)
{
    // dwData is the value returned from Init
    int i;
    for(i=0 ; i<MAX_HANDLES ; i++)
        if (handles[i]==NULL)
            break;
    if (i==MAX_HANDLES) {
        log("%08lx Open: ERROR too many open files\n");
        SetLastError(ERROR_TOO_MANY_OPEN_FILES);
        return NULL;
    }
    struct handle_info *hi = handles[i] = (struct handle_info *)LocalAlloc(LMEM_FIXED, sizeof(struct handle_info));
    if (hi==NULL) {
        log("%08lx Open: ERROR alloc: %08lx\n", GetCurrentThreadId(), GetLastError());
        SetLastError(ERROR_TOO_MANY_OPEN_FILES);
        return NULL;
    }
    hi->idx= i;
    hi->dwMagic= MYMAGIC;
    hi->tLastTimestamp=0;

    SetLastError(0);
    DWORD t0= GetTickCount();
    if (hLib)
        hi->dwTarget= DrvOpen(dwDriver, dwAccess, dwShareMode);
    else
        hi->hTarget= CreateFile(targetdev, dwAccess, dwShareMode, NULL, OPEN_EXISTING, FILE_ATTRIBUTE_NORMAL, NULL);
    DWORD stat= GetLastError();
    DWORD t1= GetTickCount();

    if (verbose&VERBOSE_BINARY)
        openbinlog(hi);

    log("%08lx %08lx-%08lx Open(%ls, %08lx,%08lx) -> %08lx:%08lx (stat=%08lx)\n", GetCurrentThreadId(), t0, t1, 
            targetdev , dwAccess, dwShareMode, hi, hi->hTarget, stat);
    if (hi->hTarget==INVALID_HANDLE_VALUE) {
        Close((DWORD)hi);
        hi=NULL;
    }
    dumpthreadinfo(GetCurrentThreadId());
    SetLastError(stat);

    return (DWORD)hi;
}
BOOL IOControl( DWORD Handle, DWORD dwIoControlCode, PBYTE pInBuf, DWORD nInBufSize, PBYTE pOutBuf, DWORD nOutBufSize, PDWORD pBytesReturned)
{
    struct handle_info *hi= (struct handle_info *)Handle;
    if (!CheckHandle("IOControl", hi))
        return FALSE;
    if (dwIoControlCode==0x47534d4b) {
        if (verbose&VERBOSE_BINARY)
            flushbinlog(hi);
        return TRUE;
    }
    BYTE *origInBuf= (BYTE*)LocalAlloc(LMEM_FIXED, nInBufSize);
    memcpy(origInBuf, pInBuf, nInBufSize);

    SetLastError(0);
    DWORD t0= GetTickCount();
    BOOL rc;
    if (hLib)
        rc = DrvIOControl(hi->dwTarget, dwIoControlCode, pInBuf, nInBufSize, pOutBuf, nOutBufSize, pBytesReturned);
    else
        rc= DeviceIoControl(hi->hTarget, dwIoControlCode, pInBuf, nInBufSize, pOutBuf, nOutBufSize, pBytesReturned, NULL);
    DWORD stat=GetLastError();
    DWORD t1= GetTickCount();

    if (verbose&VERBOSE_IOCONTROL) {
        log("%08lx %08lx-%08lx devio(%08lx:%08lx, %08lx,  %08lx, %08lx,  %08lx, %08lx,  %08lx:%d) -> %08lx ( stat=%08lx )\n", GetCurrentThreadId(),
                t0, t1,
                hi,hi->hTarget, dwIoControlCode, 
                pInBuf, nInBufSize, 
                pOutBuf, nOutBufSize, 
                pBytesReturned, pBytesReturned?*pBytesReturned:0, 
                rc, stat);

        hexdump(t0, "in0", origInBuf, nInBufSize);
        if (memcmp(origInBuf, pInBuf, nInBufSize))
            hexdump(t0, "in1", pInBuf, nInBufSize);
        hexdump(t0, "out", pOutBuf, nOutBufSize);
        dumpthreadinfo(GetCurrentThreadId());
    }
    LocalFree(origInBuf);
    SetLastError(stat);
    return rc;
}
DWORD Read(DWORD Handle, LPVOID pBuffer, DWORD dwNumBytes)
{
    struct handle_info *hi= (struct handle_info *)Handle;
    if (!CheckHandle("Read", hi))
        return 0xFFFFFFFF;

    DWORD nRead=0;

    SetLastError(0);
    DWORD t0= GetTickCount();
    BOOL rc;
    if (hLib) {
        nRead= DrvRead(hi->dwTarget, pBuffer, dwNumBytes);
        rc= (nRead!=0xFFFFFFFF);
    }
    else
        rc= ReadFile(hi->hTarget, pBuffer, dwNumBytes, &nRead, NULL);
    DWORD stat=GetLastError();
    DWORD t1= GetTickCount();

    if ((verbose&VERBOSE_READWRITE)==0) {
        // don't log
    }
    else if (nRead==0 && rc) {
        // don't log
    }
    else if (rc && nRead) {
        log("%08lx %08lx-%08lx: Read(%08lx:%08lx, %08lx, %08lx) -> %08lx, n=%08lx, stat=%08lx\n", GetCurrentThreadId(),
             t0, t1,      hi, hi->hTarget, pBuffer, dwNumBytes, rc, nRead, stat);
        hexdump(t0, "Read", (BYTE*)pBuffer, nRead);
        dumpthreadinfo(GetCurrentThreadId());
    }
    else if (!rc) {
        log("%08lx %08lx-%08lx: Read(%08lx:%08lx, %08lx, %08lx) -> %08lx, n=%08lx, stat=%08lx\n", GetCurrentThreadId(),
             t0, t1,      hi, hi->hTarget, pBuffer, dwNumBytes, rc, nRead, stat);
        dumpthreadinfo(GetCurrentThreadId());
    }
    if ((verbose&VERBOSE_BINARY)!=0 && nRead)
        binarylog(hi, t0, LOGTYPE_READ, (BYTE*)pBuffer, nRead);
    SetLastError(stat);
    if (rc)
        return nRead;
    else
        return 0xFFFFFFFF;
}
DWORD Write(DWORD Handle, LPCVOID pBuffer, DWORD dwNumBytes)
{
    struct handle_info *hi= (struct handle_info *)Handle;
    if (!CheckHandle("Write", hi))
        return 0xFFFFFFFF;
    DWORD nWritten=0;

    SetLastError(0);
    DWORD t0= GetTickCount();
    BOOL rc;
    if (hLib) {
        nWritten= DrvWrite(hi->dwTarget, pBuffer, dwNumBytes);
        rc= (nWritten!=0xFFFFFFFF);
    }
    else
        rc= WriteFile(hi->hTarget, pBuffer, dwNumBytes, &nWritten, NULL);
    DWORD stat=GetLastError();
    DWORD t1= GetTickCount();

    if ((verbose&VERBOSE_READWRITE)==0) {
        // don't log
    }
    else {
        log("%08lx %08lx-%08lx: Writ(%08lx:%08lx, %08lx, %08lx) -> %08lx, n=%08lx, stat=%08lx\n", GetCurrentThreadId(),
                t0, t1, hi, hi->hTarget, pBuffer, dwNumBytes, rc, nWritten, stat);
        if (rc && nWritten)
            hexdump(t0, "Writ", (BYTE*)pBuffer, dwNumBytes);
        dumpthreadinfo(GetCurrentThreadId());
    }
    if (verbose&VERBOSE_BINARY)
        binarylog(hi, t0, LOGTYPE_WRITE, (BYTE*)pBuffer, dwNumBytes);
    SetLastError(stat);
    if (rc)
        return nWritten;
    else
        return 0xFFFFFFFF;

}
DWORD Seek(DWORD Handle, long lDistance, DWORD dwMoveMethod)
{
    struct handle_info *hi= (struct handle_info *)Handle;
    if (!CheckHandle("IOControl", hi))
        return 0xFFFFFFFF;

    SetLastError(0);
    DWORD t0= GetTickCount();
    DWORD rc;
    if (hLib)
        rc= DrvSeek(hi->dwTarget, lDistance, dwMoveMethod);
    else
        rc= SetFilePointer(hi->hTarget, lDistance, 0, dwMoveMethod);
    DWORD stat=GetLastError();
    DWORD t1= GetTickCount();

    log("%08lx %08lx-%08lx: Seek(%08lx:%08lx, %08lx, %08lx) -> %08lx, stat=%08lx\n", GetCurrentThreadId(),
            t0, t1, hi, hi->hTarget, lDistance, dwMoveMethod, rc, stat);

    SetLastError(stat);
    return rc;
}
void PowerUp(void)
{
    log("%08lx %08lx: powerup\n", GetCurrentThreadId(), GetTickCount());
    if (hLib)
        DrvPowerUp();
}
void PowerDown(void)
{
    log("%08lx %08lx: powerdown\n", GetCurrentThreadId(), GetTickCount());
    if (hLib)
        DrvPowerDown();
}