#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 "kernelmisc.h"
#include "stringutils.h"
#include "devicedriverloader.h"
#include "RegistryFunctions.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 dwRegContext);
EXPORT BOOL Close( DWORD dwHandle);
EXPORT BOOL Deinit( DWORD dwDrvContext);
EXPORT DWORD Open( DWORD dwdrvcontext, DWORD dwAccess, DWORD dwShareMode);
EXPORT BOOL IOControl( DWORD dwHandle, DWORD dwIoControlCode, PBYTE pInBuf, DWORD nInBufSize, PBYTE pOutBuf, DWORD nOutBufSize, PDWORD pBytesReturned);
EXPORT DWORD Read(DWORD dwHandle, LPVOID pBuffer, DWORD dwNumBytes);
EXPORT DWORD Write(DWORD dwHandle, LPCVOID pBuffer, DWORD dwNumBytes);
EXPORT DWORD Seek(DWORD dwHandle, long lDistance, DWORD dwMoveMethod);
EXPORT void PowerUp(DWORD dwDrvContext);
EXPORT void PowerDown(DWORD dwDrvContext);
}



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

#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;

#if 0
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);
}
#endif
#define log printf
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';
#if 0
        writelog(line, i);
#endif
        line[i]= 0;
        printf("%s\n", line);
    }
}
//-------------------------------------------------------------------
//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("LD-threadinfo %08lx->%08lx, cur=%s owner=%s\n", tid, thrd, dumpprocinfo(thrd->pProc).c_str(), dumpprocinfo(thrd->pOwnerProc).c_str());

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

//-------------------------------------------------------------------
BOOL APIENTRY DllMain( HANDLE hModule,
                       DWORD  ul_reason_for_call,
                       LPVOID lpReserved
                     )
{
    KernelMode _km;
    if (ul_reason_for_call==DLL_PROCESS_ATTACH) {
#if 0
        openlog();
#endif
        log("LD-%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) {
#if 0
        closelog();
#endif
    }
    dumpthreadinfo(GetCurrentThreadId());
    return TRUE;
}
//-------------------------------------------------------------------
#define MYMAGIC 0x98761234
#define FILEDEVICE ((devicedriverloader*)1)
#define MAX_HANDLES 256
struct handle_info {
    DWORD dwMagic;
    devicedriverloader *drv;
    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("LD-%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);
}

bool isFileDevice(devicedriverloader*d)
{
    return (DWORD(d)&1)==1;
}
TCHAR *getFileDevice(devicedriverloader*d)
{
    return (TCHAR*)(DWORD(d)&~1);
}

//-------------------------------------------------------------------
DWORD Init( DWORD dwRegContext)
{
    KernelMode _km;
    // todo: change this to:
    // HKEY hDevkey= OpenDeviceKey(dwRegContext);
    // ReadRegistryString(hDevkey, NULL, _T("target"), targetdev, MAX_PATH)


    // targetdev is either a devicename ( like 'RDO2:' )
    // or a devicekey ( like 'Drivers\BuiltIn\QRADIO' )
    TCHAR targetdev[MAX_PATH];

    TCHAR devkey[MAX_PATH];


    if (!ReadRegistryString(HKEY_LOCAL_MACHINE, (LPTSTR)dwRegContext, _T("Key"), devkey, MAX_PATH)) {
        log("LD-%08lx Init: ERROR getting target device key from %ls\n", GetCurrentThreadId(), dwRegContext);
        return NULL;
    }
    if (!ReadRegistryString(HKEY_LOCAL_MACHINE, devkey, _T("target"), targetdev, MAX_PATH)) {
        log("LD-%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("LD-%08lx %08lx: Init(%ls): file dev=%ls\n", GetCurrentThreadId(), GetTickCount(), dwRegContext, targetdev);
        dumpthreadinfo(GetCurrentThreadId());
        TCHAR *tname= _tcsdup(targetdev);
        return ((DWORD)tname)|1;
    }
    else {
        log("LD-%08lx %08lx: Init(%ls): thnk dev=%ls\n", GetCurrentThreadId(), GetTickCount(), dwRegContext, targetdev);
        devicedriverloader *drv= new devicedriverloader();
        if (!drv->load((const TCHAR*)dwRegContext)) {
            delete drv;
            drv= NULL;
        }
        return (DWORD)drv;
    }
}


BOOL Close( DWORD Handle)
{
    KernelMode _km;
    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 (!isFileDevice(hi->drv))
            rc= hi->drv->DrvClose(hi->dwTarget);
        else
            rc= CloseHandle(hi->hTarget);
        stat=GetLastError();
        t1= GetTickCount();

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

    handles[hi->idx]=NULL;
    LocalFree(hi);
    SetLastError(stat);
    return rc;
}
BOOL Deinit( DWORD dwDrvContext)
{
    KernelMode _km;
    for(int i=0 ; i<MAX_HANDLES ; i++)
        if (handles[i])
            Close((DWORD)handles[i]);
    devicedriverloader *drv= (devicedriverloader *)dwDrvContext;
    log("LD%08lx-%08lx %08lx: Deinit(%08lx)\n", drv, GetCurrentThreadId(), GetTickCount(), dwDrvContext);
    if (!isFileDevice(drv))
        delete drv;
    else
        free(getFileDevice(drv));

    return TRUE;
}
DWORD Open( DWORD dwDrvContext, DWORD dwAccess, DWORD dwShareMode)
{
    KernelMode _km;
    // dwDrvContext is the value returned from Init
    devicedriverloader *drv= (devicedriverloader *)dwDrvContext;

    struct handle_info *hi = (struct handle_info *)LocalAlloc(LMEM_FIXED, sizeof(struct handle_info));
    if (hi==NULL) {
        log("LD%08lx-%08lx Open: ERROR alloc: %08lx\n", drv, GetCurrentThreadId(), GetLastError());
        SetLastError(ERROR_TOO_MANY_OPEN_FILES);
        return NULL;
    }

    int i;
    for(i=0 ; i<MAX_HANDLES ; i++)
        if (InterlockedCompareExchange((LPLONG)&handles[i], (DWORD)hi, 0)==0)
            break;
    if (i==MAX_HANDLES) {
        log("LD%08lx-%08lx Open: ERROR too many open files\n", drv, GetCurrentThreadId());
        SetLastError(ERROR_TOO_MANY_OPEN_FILES);
        return NULL;
    }
    hi->drv= drv;
    hi->idx= i;
    hi->dwMagic= MYMAGIC;
    hi->tLastTimestamp=0;

    SetLastError(0);
    DWORD t0= GetTickCount();
    if (!isFileDevice(drv))
        hi->dwTarget= drv->open(dwAccess, dwShareMode);
    else
        hi->hTarget= CreateFile(getFileDevice(drv), dwAccess, dwShareMode, NULL, OPEN_EXISTING, FILE_ATTRIBUTE_NORMAL, NULL);
    DWORD stat= GetLastError();
    DWORD t1= GetTickCount();

    if (verbose&VERBOSE_BINARY)
        openbinlog(hi);

    log("LD%08lx-%08lx t:%08lx-%08lx Open(%ls, %08lx,%08lx) -> %08lx:%08lx (stat=%08lx)\n",
            drv, GetCurrentThreadId(), t0, t1, 
            getFileDevice(drv), 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)
{
    KernelMode _km;
    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 (!isFileDevice(hi->drv))
        rc = hi->drv->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("LD%08lx-%08lx t:%08lx-%08lx devio(%08lx:%08lx, %08lx,  %08lx, %08lx,  %08lx, %08lx,  %08lx:%d) -> %08lx ( stat=%08lx )\n", 
                hi->drv, 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)
{
    KernelMode _km;
    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 (!isFileDevice(hi->drv)) {
        nRead= hi->drv->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("LD%08lx-%08lx t:%08lx-%08lx: Read(%08lx:%08lx, %08lx, %08lx) -> %08lx, n=%08lx, stat=%08lx\n", 
             hi->drv, GetCurrentThreadId(),
             t0, t1,      hi, hi->hTarget, pBuffer, dwNumBytes, rc, nRead, stat);
        hexdump(t0, "Read", (BYTE*)pBuffer, nRead);
        dumpthreadinfo(GetCurrentThreadId());
    }
    else if (!rc) {
        log("LD%08lx-%08lx t:%08lx-%08lx: Read(%08lx:%08lx, %08lx, %08lx) -> %08lx, n=%08lx, stat=%08lx\n",
             hi->drv, 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)
{
    KernelMode _km;
    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 (!isFileDevice(hi->drv)) {
        nWritten= hi->drv->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("LD%08lx-%08lx %08lx-%08lx: Writ(%08lx:%08lx, %08lx, %08lx) -> %08lx, n=%08lx, stat=%08lx\n", 
                hi->drv, 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)
{
    KernelMode _km;
    struct handle_info *hi= (struct handle_info *)Handle;
    if (!CheckHandle("IOControl", hi))
        return 0xFFFFFFFF;

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

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

    SetLastError(stat);
    return rc;
}
void PowerUp(DWORD dwDrvContext)
{
    KernelMode _km;
    log("LD%08lx-%08lx %08lx: powerup\n", dwDrvContext, GetCurrentThreadId(), GetTickCount());
    devicedriverloader *drv= (devicedriverloader *)dwDrvContext;
    if (drv)
        drv->DrvPowerUp(drv->_dwDriver);
}
void PowerDown(DWORD dwDrvContext)
{
    KernelMode _km;
    log("LD%08lx-%08lx %08lx: powerdown\n", dwDrvContext, GetCurrentThreadId(), GetTickCount());
    devicedriverloader *drv= (devicedriverloader *)dwDrvContext;
    if (drv)
        drv->DrvPowerDown(drv->_dwDriver);
}