Skip to content
GitLab
Open
Issue created by Derek Bruening@derekbrueningContributor

win32.hookerfirst started failing on vs2017_32 with output mismatch

win32.hookerfirst failed in vs2017-32 here: https://github.com/DynamoRIO/dynamorio/pull/4869/checks?check_run_id=2412466700

It's some kind of output mismatch. I don't think we've see it fail before: not clear what might have triggered this. Windows upgrade?

2021-04-22T17:04:41.1345671Z  55/236 Test  #55: code_api|win32.hookerfirst ...................................***Failed  Required regular expression not found. Regex=[^ready to hook 1
2021-04-22T17:04:41.1346477Z ?
2021-04-22T17:04:41.1346817Z ok: can't write
2021-04-22T17:04:41.1347167Z ?
2021-04-22T17:04:41.1347950Z VirtualProtect\(NtTerminateProcess\[0x00000000\],4096,PAGE_EXECUTE_READWRITE,prev\) = 0 GLE=00000000 prev=00000020
2021-04-22T17:04:41.1348721Z ?
2021-04-22T17:04:41.1349178Z hooked NtTerminateProcess
2021-04-22T17:04:41.1349637Z ?
2021-04-22T17:04:41.1350297Z VirtualProtect\(NtTerminateProcess\[0x00000000\],4096,PAGE_EXECUTE_READ,\.\.\.\) = 0 GLE=00000000
2021-04-22T17:04:41.1351196Z ?
2021-04-22T17:04:41.1351620Z old permissions \.\.\.prev=00000040\)
2021-04-22T17:04:41.1352025Z ?
2021-04-22T17:04:41.1352362Z ok: can't write
2021-04-22T17:04:41.1352712Z ?
2021-04-22T17:04:41.1353042Z do_hook\(\) done
2021-04-22T17:04:41.1353386Z ?
2021-04-22T17:04:41.1353724Z ok: can't write
2021-04-22T17:04:41.1354214Z ?
2021-04-22T17:04:41.1354967Z VirtualProtect\(NtTerminateThread\[0x00000000\],4096,PAGE_EXECUTE_READWRITE,prev\) = 0 GLE=00000000 prev=00000020
2021-04-22T17:04:41.1355702Z ?
2021-04-22T17:04:41.1356135Z hooked NtTerminateThread
2021-04-22T17:04:41.1356582Z ?
2021-04-22T17:04:41.1357241Z VirtualProtect\(NtTerminateThread\[0x00000000\],4096,PAGE_EXECUTE_READ,\.\.\.\) = 0 GLE=00000000
2021-04-22T17:04:41.1357883Z ?
2021-04-22T17:04:41.1358305Z old permissions \.\.\.prev=00000040\)
2021-04-22T17:04:41.1358722Z ?
2021-04-22T17:04:41.1359046Z ok: can't write
2021-04-22T17:04:41.1359386Z ?
2021-04-22T17:04:41.1359721Z do_hook\(\) done
2021-04-22T17:04:41.1360052Z ?
2021-04-22T17:04:41.1360459Z ok: can't write
2021-04-22T17:04:41.1360801Z ?
2021-04-22T17:04:41.1361545Z VirtualProtect\(NtFlushWriteBuffer\[0x00000000\],4096,PAGE_EXECUTE_READWRITE,prev\) = 0 GLE=00000000 prev=00000020
2021-04-22T17:04:41.1362282Z ?
2021-04-22T17:04:41.1362727Z hooked NtFlushWriteBuffer
2021-04-22T17:04:41.1363169Z ?
2021-04-22T17:04:41.1363898Z VirtualProtect\(NtFlushWriteBuffer\[0x00000000\],4096,PAGE_EXECUTE_READ,\.\.\.\) = 0 GLE=00000000
2021-04-22T17:04:41.1364552Z ?
2021-04-22T17:04:41.1364952Z old permissions \.\.\.prev=00000040\)
2021-04-22T17:04:41.1365370Z ?
2021-04-22T17:04:41.1365705Z ok: can't write
2021-04-22T17:04:41.1366034Z ?
2021-04-22T17:04:41.1366372Z do_hook\(\) done
2021-04-22T17:04:41.1366712Z ?
2021-04-22T17:04:41.1367055Z hooking done with
2021-04-22T17:04:41.1367413Z ?
2021-04-22T17:04:41.1367781Z hookerfirst main\(\)
2021-04-22T17:04:41.1368154Z ?
2021-04-22T17:04:41.1368534Z \*\*\* invalid ret allowed!
2021-04-22T17:04:41.1368928Z ?
2021-04-22T17:04:41.1369265Z ready to unhook 37
2021-04-22T17:04:41.1369618Z ?
2021-04-22T17:04:41.1370429Z VirtualProtect\(NtTerminateProcess\[0x00000000\],4096,PAGE_EXECUTE_READWRITE,prev\) = 0 GLE=00000000 prev=00000020
2021-04-22T17:04:41.1371181Z ?
2021-04-22T17:04:41.1371674Z there be witches! what happened to my previous hook\?
2021-04-22T17:04:41.1372180Z ?
2021-04-22T17:04:41.1372864Z there be witches! my good unhooking intentions were squashed on NtTerminateProcess
2021-04-22T17:04:41.1373527Z ?
2021-04-22T17:04:41.1373889Z restored old code
2021-04-22T17:04:41.1374256Z ?
2021-04-22T17:04:41.1374909Z VirtualProtect\(NtTerminateProcess\[0x00000000\],4096,PAGE_EXECUTE_READ,\.\.\.\) = 0 GLE=00000000
2021-04-22T17:04:41.1375571Z ?
2021-04-22T17:04:41.1376090Z old permissions \.\.\.prev=00000020\)
2021-04-22T17:04:41.1376494Z ?
2021-04-22T17:04:41.1376829Z ok: can't write
2021-04-22T17:04:41.1377173Z ?
2021-04-22T17:04:41.1387751Z do_unhook\(\) done
2021-04-22T17:04:41.1388317Z ?
2021-04-22T17:04:41.1389097Z VirtualProtect\(NtTerminateThread\[0x00000000\],4096,PAGE_EXECUTE_READWRITE,prev\) = 0 GLE=00000000 prev=00000020
2021-04-22T17:04:41.1389832Z ?
2021-04-22T17:04:41.1390343Z there be witches! what happened to my previous hook\?
2021-04-22T17:04:41.1390929Z ?
2021-04-22T17:04:41.1391594Z there be witches! my good unhooking intentions were squashed on NtTerminateThread
2021-04-22T17:04:41.1392286Z ?
2021-04-22T17:04:41.1392653Z restored old code
2021-04-22T17:04:41.1393009Z ?
2021-04-22T17:04:41.1393689Z VirtualProtect\(NtTerminateThread\[0x00000000\],4096,PAGE_EXECUTE_READ,\.\.\.\) = 0 GLE=00000000
2021-04-22T17:04:41.1394348Z ?
2021-04-22T17:04:41.1394977Z old permissions \.\.\.prev=00000020\)
2021-04-22T17:04:41.1396490Z ?
2021-04-22T17:04:41.1397049Z ok: can't write
2021-04-22T17:04:41.1397386Z ?
2021-04-22T17:04:41.1397737Z do_unhook\(\) done
2021-04-22T17:04:41.1398095Z ?
2021-04-22T17:04:41.1398844Z VirtualProtect\(NtFlushWriteBuffer\[0x00000000\],4096,PAGE_EXECUTE_READWRITE,prev\) = 0 GLE=00000000 prev=00000020
2021-04-22T17:04:41.1399589Z ?
2021-04-22T17:04:41.1400072Z my hook is still there, will remove now
2021-04-22T17:04:41.1400548Z ?
2021-04-22T17:04:41.1401230Z there be witches! my good unhooking intentions were squashed on NtFlushWriteBuffer
2021-04-22T17:04:41.1401903Z ?
2021-04-22T17:04:41.1402907Z restored old code
2021-04-22T17:04:41.1404237Z ?
2021-04-22T17:04:41.1404929Z VirtualProtect\(NtFlushWriteBuffer\[0x00000000\],4096,PAGE_EXECUTE_READ,\.\.\.\) = 0 GLE=00000000
2021-04-22T17:04:41.1405588Z ?
2021-04-22T17:04:41.1405989Z old permissions \.\.\.prev=00000020\)
2021-04-22T17:04:41.1406404Z ?
2021-04-22T17:04:41.1406747Z ok: can't write
2021-04-22T17:04:41.1407085Z ?
2021-04-22T17:04:41.1407487Z do_unhook\(\) done
2021-04-22T17:04:41.1407850Z ?
2021-04-22T17:04:41.1408204Z unhooking done with
2021-04-22T17:04:41.1408573Z ?
2021-04-22T17:04:41.1408911Z ready to hook 37
2021-04-22T17:04:41.1409244Z ?
2021-04-22T17:04:41.1409582Z ok: can't write
2021-04-22T17:04:41.1409913Z ?
2021-04-22T17:04:41.1410742Z VirtualProtect\(NtTerminateProcess\[0x00000000\],4096,PAGE_EXECUTE_READWRITE,prev\) = 0 GLE=00000000 prev=00000020
2021-04-22T17:04:41.1411489Z ?
2021-04-22T17:04:41.1411961Z there be witches! what happened to my write\?
2021-04-22T17:04:41.1412417Z ?
2021-04-22T17:04:41.1413096Z VirtualProtect\(NtTerminateProcess\[0x00000000\],4096,PAGE_EXECUTE_READ,\.\.\.\) = 0 GLE=00000000
2021-04-22T17:04:41.1413763Z ?
2021-04-22T17:04:41.1414161Z old permissions \.\.\.prev=00000020\)
2021-04-22T17:04:41.1414578Z ?
2021-04-22T17:04:41.1414921Z ok: can't write
2021-04-22T17:04:41.1415253Z ?
2021-04-22T17:04:41.1415683Z do_hook\(\) done
2021-04-22T17:04:41.1416059Z ?
2021-04-22T17:04:41.1416511Z ok: can't write
2021-04-22T17:04:41.1416924Z ?
2021-04-22T17:04:41.1417707Z VirtualProtect\(NtTerminateThread\[0x00000000\],4096,PAGE_EXECUTE_READWRITE,prev\) = 0 GLE=00000000 prev=00000020
2021-04-22T17:04:41.1418509Z ?
2021-04-22T17:04:41.1419061Z there be witches! what happened to my write\?
2021-04-22T17:04:41.1419545Z ?
2021-04-22T17:04:41.1420270Z VirtualProtect\(NtTerminateThread\[0x00000000\],4096,PAGE_EXECUTE_READ,\.\.\.\) = 0 GLE=00000000
2021-04-22T17:04:41.1421032Z ?
2021-04-22T17:04:41.1421463Z old permissions \.\.\.prev=00000020\)
2021-04-22T17:04:41.1421955Z ?
2021-04-22T17:04:41.1431843Z ok: can't write
2021-04-22T17:04:41.1432317Z ?
2021-04-22T17:04:41.1432680Z do_hook\(\) done
2021-04-22T17:04:41.1433046Z ?
2021-04-22T17:04:41.1433378Z ok: can't write
2021-04-22T17:04:41.1433741Z ?
2021-04-22T17:04:41.1434525Z VirtualProtect\(NtFlushWriteBuffer\[0x00000000\],4096,PAGE_EXECUTE_READWRITE,prev\) = 0 GLE=00000000 prev=00000020
2021-04-22T17:04:41.1435270Z ?
2021-04-22T17:04:41.1435907Z hooked NtFlushWriteBuffer
2021-04-22T17:04:41.1436378Z ?
2021-04-22T17:04:41.1437049Z VirtualProtect\(NtFlushWriteBuffer\[0x00000000\],4096,PAGE_EXECUTE_READ,\.\.\.\) = 0 GLE=00000000
2021-04-22T17:04:41.1437727Z ?
2021-04-22T17:04:41.1438163Z old permissions \.\.\.prev=00000020\)
2021-04-22T17:04:41.1438577Z ?
2021-04-22T17:04:41.1438925Z ok: can't write
2021-04-22T17:04:41.1439281Z ?
2021-04-22T17:04:41.1439616Z do_hook\(\) done
2021-04-22T17:04:41.1439976Z ?
2021-04-22T17:04:41.1440346Z hooking done with
2021-04-22T17:04:41.1440794Z ?
2021-04-22T17:04:41.1441172Z ready to unhook 37
2021-04-22T17:04:41.1441542Z ?
2021-04-22T17:04:41.1442300Z VirtualProtect\(NtTerminateProcess\[0x00000000\],4096,PAGE_EXECUTE_READWRITE,prev\) = 0 GLE=00000000 prev=00000020
2021-04-22T17:04:41.1443065Z ?
2021-04-22T17:04:41.1443517Z my hook is still there, will remove now
2021-04-22T17:04:41.1443937Z ?
2021-04-22T17:04:41.1444416Z unhooked NtTerminateProcess
2021-04-22T17:04:41.1444898Z ?
2021-04-22T17:04:41.1445261Z restored old code
2021-04-22T17:04:41.1445635Z ?
2021-04-22T17:04:41.1446319Z VirtualProtect\(NtTerminateProcess\[0x00000000\],4096,PAGE_EXECUTE_READ,\.\.\.\) = 0 GLE=00000000
2021-04-22T17:04:41.1446994Z ?
2021-04-22T17:04:41.1447406Z old permissions \.\.\.prev=00000020\)
2021-04-22T17:04:41.1447845Z ?
2021-04-22T17:04:41.1448200Z ok: can't write
2021-04-22T17:04:41.1448538Z ?
2021-04-22T17:04:41.1448897Z do_unhook\(\) done
2021-04-22T17:04:41.1449244Z ?
2021-04-22T17:04:41.1450009Z VirtualProtect\(NtTerminateThread\[0x00000000\],4096,PAGE_EXECUTE_READWRITE,prev\) = 0 GLE=00000000 prev=00000020
2021-04-22T17:04:41.1450902Z ?
2021-04-22T17:04:41.1451351Z my hook is still there, will remove now
2021-04-22T17:04:41.1451775Z ?
2021-04-22T17:04:41.1452244Z unhooked NtTerminateThread
2021-04-22T17:04:41.1452727Z ?
2021-04-22T17:04:41.1453080Z restored old code
2021-04-22T17:04:41.1453460Z ?
2021-04-22T17:04:41.1454142Z VirtualProtect\(NtTerminateThread\[0x00000000\],4096,PAGE_EXECUTE_READ,\.\.\.\) = 0 GLE=00000000
2021-04-22T17:04:41.1454777Z ?
2021-04-22T17:04:41.1455193Z old permissions \.\.\.prev=00000020\)
2021-04-22T17:04:41.1455618Z ?
2021-04-22T17:04:41.1455950Z ok: can't write
2021-04-22T17:04:41.1456310Z ?
2021-04-22T17:04:41.1456672Z do_unhook\(\) done
2021-04-22T17:04:41.1457024Z ?
2021-04-22T17:04:41.1457793Z VirtualProtect\(NtFlushWriteBuffer\[0x00000000\],4096,PAGE_EXECUTE_READWRITE,prev\) = 0 GLE=00000000 prev=00000020
2021-04-22T17:04:41.1458532Z ?
2021-04-22T17:04:41.1458957Z my hook is still there, will remove now
2021-04-22T17:04:41.1459409Z ?
2021-04-22T17:04:41.1459882Z unhooked NtFlushWriteBuffer
2021-04-22T17:04:41.1460340Z ?
2021-04-22T17:04:41.1460770Z restored old code
2021-04-22T17:04:41.1461154Z ?
2021-04-22T17:04:41.1461814Z VirtualProtect\(NtFlushWriteBuffer\[0x00000000\],4096,PAGE_EXECUTE_READ,\.\.\.\) = 0 GLE=00000000
2021-04-22T17:04:41.1462488Z ?
2021-04-22T17:04:41.1462917Z old permissions \.\.\.prev=00000020\)
2021-04-22T17:04:41.1463326Z ?
2021-04-22T17:04:41.1463683Z ok: can't write
2021-04-22T17:04:41.1464043Z ?
2021-04-22T17:04:41.1464378Z do_unhook\(\) done
2021-04-22T17:04:41.1464745Z ?
2021-04-22T17:04:41.1465129Z unhooking done with
2021-04-22T17:04:41.1465499Z ?
2021-04-22T17:04:41.1465818Z $
2021-04-22T17:04:41.1466145Z ]  0.33 sec
2021-04-22T17:04:41.1466501Z ready to hook 1
2021-04-22T17:04:41.1466902Z ok: can't write
2021-04-22T17:04:41.1467700Z VirtualProtect(NtTerminateProcess[0x00000000],4096,PAGE_EXECUTE_READWRITE,prev) = 0 GLE=00000000 prev=00000020
2021-04-22T17:04:41.1468590Z hooked NtTerminateProcess
2021-04-22T17:04:41.1469416Z VirtualProtect(NtTerminateProcess[0x00000000],4096,PAGE_EXECUTE_READ,...) = 0 GLE=00000000
2021-04-22T17:04:41.1470190Z old permissions ...prev=00000040)
2021-04-22T17:04:41.1485090Z ok: can't write
2021-04-22T17:04:41.1485523Z do_hook() done
2021-04-22T17:04:41.1485925Z ok: can't write
2021-04-22T17:04:41.1486873Z VirtualProtect(NtTerminateThread[0x00000000],4096,PAGE_EXECUTE_READWRITE,prev) = 0 GLE=00000000 prev=00000020
2021-04-22T17:04:41.1487766Z hooked NtTerminateThread
2021-04-22T17:04:41.1488580Z VirtualProtect(NtTerminateThread[0x00000000],4096,PAGE_EXECUTE_READ,...) = 0 GLE=00000000
2021-04-22T17:04:41.1489355Z old permissions ...prev=00000040)
2021-04-22T17:04:41.1489796Z ok: can't write
2021-04-22T17:04:41.1490192Z do_hook() done
2021-04-22T17:04:41.1490663Z ok: can't write
2021-04-22T17:04:41.1491442Z VirtualProtect(NtFlushWriteBuffer[0x00000000],4096,PAGE_EXECUTE_READWRITE,prev) = 0 GLE=00000000 prev=00000020
2021-04-22T17:04:41.1492343Z hooked NtFlushWriteBuffer
2021-04-22T17:04:41.1493161Z VirtualProtect(NtFlushWriteBuffer[0x00000000],4096,PAGE_EXECUTE_READ,...) = 0 GLE=00000000
2021-04-22T17:04:41.1493903Z old permissions ...prev=00000040)
2021-04-22T17:04:41.1494368Z ok: can't write
2021-04-22T17:04:41.1494759Z do_hook() done
2021-04-22T17:04:41.1495152Z hooking done with
2021-04-22T17:04:41.1495439Z

Actually I see a ref to one other failure at https://github.com/DynamoRIO/dynamorio/pull/4867/checks?check_run_id=2411078636