Просмотр исходного кода

M2: per-request context, central error/outcome logging, three real WSC/VBScript defects fixed

- RequestContext.wsc: per-request path/method/correlationId/elapsed-time,
  primitive-only, no ASP intrinsics
- Application.Run(ctx, ...) centralizes expected-vs-unexpected outcomes and
  best-effort logging to logs/app.log (lock-file mutex, no ASP Application
  intrinsic available by contract)
- Fixed: Property Get requires a Class block, fails at WSC top level
  (regsvr32 exit 5) -> switched to plain Function-based getters
- Fixed: FormatNumber() leaks a locale comma into correlation ids
- Fixed: Randomize+Rnd() collide within the same clock tick -> switched to
  FileSystemObject.GetTempName()
- Verified real concurrent-logging tradeoffs experimentally (retry-the-open
  alone made it worse; lock-file mutex is correct but a full-coverage retry
  budget costs ~330ms latency, so a short budget + accepted best-effort log
  loss under heavy load is used instead)
- Investigated and resolved an inherited IUSR:(F) ACL finding under logs/
  (standard NTFS CREATOR OWNER materialization, correctly scoped, not a
  broad grant)
- All M2 SPEC/plan gate items verified PASS on real IIS; see
  docs/TEST-RESULTS.md and docs/DECISIONS.md
master
Bottybotsterson 2 недель назад
Родитель
Сommit
93455d1e49
12 измененных файлов: 470 добавлений и 43 удалений
  1. +1
    -0
      .gitignore
  2. +33
    -2
      Default.asp
  3. +133
    -6
      Framework/Application.wsc
  4. +92
    -0
      Framework/RequestContext.wsc
  5. +5
    -5
      IMPLEMENTATION_PLAN.md
  6. +22
    -10
      docs/ARCHITECTURE.md
  7. +18
    -0
      docs/DECISIONS.md
  8. +60
    -0
      docs/TEST-RESULTS.md
  9. +102
    -19
      tests/Test-Components.vbs
  10. +1
    -0
      tools/Register-Components.ps1
  11. +2
    -1
      tools/Unregister-Components.ps1
  12. +1
    -0
      web.config

+ 1
- 0
.gitignore Просмотреть файл

@@ -0,0 +1 @@
logs/

+ 33
- 2
Default.asp Просмотреть файл

@@ -1,9 +1,37 @@
<%@ Language="VBScript" %>
<% Option Explicit %>
<%
Dim route, app, statusLine, contentType, body
Dim route, httpMethod, logDir, ctx, app, statusLine, contentType, body

route = Request.QueryString("route")
httpMethod = Request.ServerVariables("REQUEST_METHOD")
logDir = Server.MapPath("logs")

Set ctx = Nothing
On Error Resume Next
Set ctx = Server.CreateObject("WscMvc.RequestContext")
If Err.Number <> 0 Then
Err.Clear
On Error Goto 0
Response.Status = "500 Internal Server Error"
Response.ContentType = "text/plain; charset=utf-8"
Response.Write "Internal Server Error"
Response.End
End If
On Error Goto 0

On Error Resume Next
ctx.Initialize route, httpMethod, logDir
If Err.Number <> 0 Then
Err.Clear
On Error Goto 0
Set ctx = Nothing
Response.Status = "500 Internal Server Error"
Response.ContentType = "text/plain; charset=utf-8"
Response.Write "Internal Server Error"
Response.End
End If
On Error Goto 0

Set app = Nothing
On Error Resume Next
@@ -11,6 +39,7 @@ Set app = Server.CreateObject("WscMvc.Application")
If Err.Number <> 0 Then
Err.Clear
On Error Goto 0
Set ctx = Nothing
Response.Status = "500 Internal Server Error"
Response.ContentType = "text/plain; charset=utf-8"
Response.Write "Internal Server Error"
@@ -23,11 +52,12 @@ contentType = ""
body = ""

On Error Resume Next
app.Run route, statusLine, contentType, body
app.Run ctx, statusLine, contentType, body
If Err.Number <> 0 Then
Err.Clear
On Error Goto 0
Set app = Nothing
Set ctx = Nothing
Response.Status = "500 Internal Server Error"
Response.ContentType = "text/plain; charset=utf-8"
Response.Write "Internal Server Error"
@@ -40,4 +70,5 @@ Response.ContentType = contentType
Response.Write body

Set app = Nothing
Set ctx = Nothing
%>

+ 133
- 6
Framework/Application.wsc Просмотреть файл

@@ -10,7 +10,7 @@

<public>
<method name="Run">
<parameter name="pathInfo"/>
<parameter name="ctx"/>
<parameter name="statusLine"/>
<parameter name="contentType"/>
<parameter name="body"/>
@@ -21,12 +21,16 @@
<![CDATA[
Option Explicit

' Primitive-only contract: scalars in, scalars out by reference.
' No ASP intrinsic objects (Request/Response/Server/Session) are referenced here.
Sub Run(pathInfo, statusLine, contentType, body)
Dim ctrl, helloBody
' Central request boundary: one place decides expected (404) vs unexpected
' (COM/method failure -> 500) outcomes, and one place logs them. ctx is our
' own WscMvc.RequestContext object (not an ASP intrinsic), carrying only
' primitive request data. No ASP intrinsics are referenced here.
Sub Run(ctx, statusLine, contentType, body)
Dim ctrl, helloBody, path

If pathInfo = "/hello" Then
path = ctx.Path

If path = "/hello" Then
Set ctrl = Nothing
On Error Resume Next
Set ctrl = CreateObject("WscMvc.HomeController")
@@ -36,6 +40,7 @@ Sub Run(pathInfo, statusLine, contentType, body)
statusLine = "500 Internal Server Error"
contentType = "text/plain; charset=utf-8"
body = "Internal Server Error"
LogOutcome ctx, statusLine
Exit Sub
End If
On Error Goto 0
@@ -50,6 +55,7 @@ Sub Run(pathInfo, statusLine, contentType, body)
contentType = "text/plain; charset=utf-8"
body = "Internal Server Error"
Set ctrl = Nothing
LogOutcome ctx, statusLine
Exit Sub
End If
On Error Goto 0
@@ -59,10 +65,131 @@ Sub Run(pathInfo, statusLine, contentType, body)
body = helloBody
Set ctrl = Nothing
Else
' Expected outcome, not a failure: no matching route yet (M3 adds a real table).
statusLine = "404 Not Found"
contentType = "text/plain; charset=utf-8"
body = "Not Found"
End If

LogOutcome ctx, statusLine
End Sub

' Best-effort diagnostics only: a logging failure must never affect the
' response. Every filesystem step is individually guarded so one bad
' operation (e.g. concurrent-write contention) just skips this line rather
' than raising to the caller.
Sub LogOutcome(ctx, statusLine)
Dim fso, logFile, logPath, lockPath, line

Set fso = Nothing
On Error Resume Next
Set fso = CreateObject("Scripting.FileSystemObject")
If Err.Number <> 0 Then
Err.Clear
On Error Goto 0
Exit Sub
End If
On Error Goto 0

On Error Resume Next
If Not fso.FolderExists(ctx.LogDir) Then
fso.CreateFolder ctx.LogDir
End If
If Err.Number <> 0 Then
Err.Clear
On Error Goto 0
Set fso = Nothing
Exit Sub
End If
On Error Goto 0

logPath = ctx.LogDir & "\app.log"
lockPath = ctx.LogDir & "\app.log.lock"

' Concurrent requests race for this one shared file. Verified experimentally
' that FileSystemObject.OpenTextFile(ForAppending) mostly SUCCEEDS for every
' concurrent caller (it is not exclusive) but their writes overwrite each
' other - a lost-update race, not an open failure - so retrying the open
' alone did not help. No ASP intrinsic (Application.Lock/UnLock) is available
' here by contract, so a manual lock-file mutex is used instead:
' CreateTextFile(path, OverwriteExisting:=False) atomically fails with
' Err.Number=58 "File already exists" when another request holds the lock -
' confirmed correct/exclusive experimentally, not assumed.
'
' The retry budget below is deliberately short. Measured under 8 genuinely
' concurrent requests: the mutex itself is correct, but making every request
' reliably win eventually needs a retry budget of 300+ attempts (~300-360ms
' of blocking) - too much added latency for a best-effort diagnostic write.
' With this short budget, heavy concurrent bursts will legitimately drop
' some log lines rather than delay the response; this is an accepted
' tradeoff for "best-effort diagnostics" (see docs/DECISIONS.md), not a
' correctness bug - the HTTP response itself is unaffected either way.
' Revisit with a real logging mechanism (e.g. per-request files aggregated
' out of band) in M6 if complete log coverage under load becomes a
' requirement.
If Not AcquireLogLock(fso, lockPath) Then
Set fso = Nothing
Exit Sub
End If

Set logFile = Nothing
On Error Resume Next
Set logFile = fso.OpenTextFile(logPath, 8, True) ' 8 = ForAppending, create if missing
If Err.Number <> 0 Then
Err.Clear
On Error Goto 0
ReleaseLogLock fso, lockPath
Set fso = Nothing
Exit Sub
End If
On Error Goto 0

line = Now & " | " & ctx.CorrelationId & " | " & ctx.HttpMethod & _
" | " & ctx.Path & " | " & statusLine & " | " & ctx.ElapsedMs() & "ms"

On Error Resume Next
logFile.WriteLine line
Err.Clear
On Error Goto 0

On Error Resume Next
logFile.Close
Err.Clear
On Error Goto 0

Set logFile = Nothing
ReleaseLogLock fso, lockPath
Set fso = Nothing
End Sub

Function AcquireLogLock(fso, lockPath)
Dim attempt, maxAttempts, lockFile, busy, spinCount
maxAttempts = 10
spinCount = 8000
AcquireLogLock = False

For attempt = 1 To maxAttempts
Set lockFile = Nothing
On Error Resume Next
Set lockFile = fso.CreateTextFile(lockPath, False) ' fails if lockPath already exists
If Err.Number = 0 Then
On Error Goto 0
lockFile.Close
Set lockFile = Nothing
AcquireLogLock = True
Exit For
End If
Err.Clear
On Error Goto 0
For busy = 1 To spinCount : Next
Next
End Function

Sub ReleaseLogLock(fso, lockPath)
On Error Resume Next
fso.DeleteFile lockPath, True
Err.Clear
On Error Goto 0
End Sub
]]>
</script>


+ 92
- 0
Framework/RequestContext.wsc Просмотреть файл

@@ -0,0 +1,92 @@
<?xml version="1.0"?>
<?component error="true" debug="false"?>
<component>
<registration
description="WscMvc RequestContext"
progid="WscMvc.RequestContext"
version="1.00"
classid="{1C36FA55-34DF-4974-94B9-D657389362B2}">
</registration>

<public>
<method name="Initialize">
<parameter name="path"/>
<parameter name="httpMethod"/>
<parameter name="logDir"/>
</method>
<method name="ElapsedMs"/>
<method name="Path"/>
<method name="HttpMethod"/>
<method name="CorrelationId"/>
<method name="LogDir"/>
</public>

<script language="VBScript">
<![CDATA[
Option Explicit

' Per-request, primitive-only data holder. Never references ASP intrinsics
' (Request/Response/Server/Session) - Default.asp resolves logDir via
' Server.MapPath before calling Initialize, and passes it in as a plain string.
'
' NOTE: `Property Get/Let/Set` requires a `Class...End Class` block in
' VBScript - it cannot be used at the top level of a WSC <script> block
' (verified experimentally: registration fails with "Must be defined inside
' a Class", error 1048). Plain Function-style getters exposed as <method>
' are used instead, matching Application.wsc/HomeController.wsc.

Dim m_path, m_httpMethod, m_logDir, m_correlationId, m_startTimer, m_initialized

m_initialized = False

Sub Initialize(path, httpMethod, logDir)
m_path = path
m_httpMethod = httpMethod
m_logDir = logDir
m_correlationId = NewCorrelationId()
m_startTimer = Timer
m_initialized = True
End Sub

Function NewCorrelationId()
' Timer/Randomize/Rnd() was tried first and FAILED experimentally: two
' Initialize calls within the same system-clock tick call `Randomize` with
' the same implicit time-based seed, so Rnd() returns the identical first
' value both times - two contexts created back-to-back got the exact same
' correlation id. FileSystemObject.GetTempName() is used instead: verified
' experimentally to return a distinct value on every call even in a tight
' loop (it does not depend on Randomize/Rnd state at all).
Dim secs, fso, tempPart
secs = Fix(Timer)
Set fso = CreateObject("Scripting.FileSystemObject")
tempPart = Replace(fso.GetTempName(), ".tmp", "")
Set fso = Nothing
NewCorrelationId = CStr(secs) & "-" & tempPart
End Function

Function ElapsedMs()
If m_initialized Then
ElapsedMs = CLng((Timer - m_startTimer) * 1000)
Else
ElapsedMs = -1
End If
End Function

Function Path()
Path = m_path
End Function

Function HttpMethod()
HttpMethod = m_httpMethod
End Function

Function CorrelationId()
CorrelationId = m_correlationId
End Function

Function LogDir()
LogDir = m_logDir
End Function
]]>
</script>
</component>

+ 5
- 5
IMPLEMENTATION_PLAN.md Просмотреть файл

@@ -19,11 +19,11 @@ Gate: a WSC can be registered, instantiated, called, unregistered, and re-regist
Gate: all M1 SPEC acceptance tests pass on IIS, or mark blocked with evidence; do not call the milestone done without host verification. **MET** — see `docs/TEST-RESULTS.md` (includes one real defect found and fixed: `regsvr32 /u` does not remove `.wsc` registration on this host).

## M2 — Lifecycle and errors
- [ ] Define per-request context and response ownership.
- [ ] Explicit creation/cleanup of objects; no shared request state.
- [ ] Central unexpected/expected error handling; headers/body commitment tests.
- [ ] Add correlation-safe diagnostics.
Gate: repeated/concurrent requests and failure cases behave predictably.
- [x] Define per-request context and response ownership.
- [x] Explicit creation/cleanup of objects; no shared request state.
- [x] Central unexpected/expected error handling; headers/body commitment tests.
- [x] Add correlation-safe diagnostics.
Gate: repeated/concurrent requests and failure cases behave predictably. **MET** — see `docs/TEST-RESULTS.md`. HTTP response correctness holds unconditionally under concurrency (8/8 correct every run); best-effort logging completeness under heavy concurrency is an accepted, documented tradeoff, not a gate failure.

## M3 — Routing
- [ ] Explicit route map with GET/POST, literal routes first.


+ 22
- 10
docs/ARCHITECTURE.md Просмотреть файл

@@ -1,4 +1,4 @@
# WSC-MVC — Architecture (as implemented through M1)
# WSC-MVC — Architecture (as implemented through M2)

## Request flow

@@ -6,35 +6,47 @@
GET /hello
-> IIS URL Rewrite rule "WscMvc-Hello" (^hello/?$)
-> /Default.asp?route=/hello
-> Server.CreateObject("WscMvc.RequestContext"); ctx.Initialize path, httpMethod, logDir
-> Server.CreateObject("WscMvc.Application")
-> Application.Run("/hello", statusLine, contentType, body) [Framework/Application.wsc]
-> Application.Run(ctx, statusLine, contentType, body) [Framework/Application.wsc]
-> CreateObject("WscMvc.HomeController")
-> HomeController.Hello(body) [Controllers/HomeController.wsc]
-> HomeController.Hello(body) [Controllers/HomeController.wsc]
-> LogOutcome ctx, statusLine (best-effort append to logs/app.log)
-> Default.asp sets Response.Status/ContentType, writes body
```

## Component boundary contract

- `Default.asp` is the only file that touches ASP intrinsic objects (`Request`, `Response`, `Server`). It contains no business logic — only reading the `route` query parameter, invoking `WscMvc.Application`, and writing the response.
- `Framework/Application.wsc` and `Controllers/HomeController.wsc` never reference `Request`/`Response`/`Server`/`Session`. All data crosses the ASP-to-WSC and WSC-to-WSC boundaries as VBScript scalars (strings), passed by VBScript's default ByRef semantics for "out" values. See `docs/DECISIONS.md` for why this sidesteps SPEC §15's open question about passing ASP intrinsics into WSC.
- Routing in M1 is a single hardcoded `If pathInfo = "/hello"` check inside `Application.Run`. This is intentionally minimal and will be replaced by the explicit allowlisted route table in M3 (`Router.wsc`); do not extend it ad hoc before that milestone.
- `Default.asp` is the only file that touches ASP intrinsic objects (`Request`, `Response`, `Server`). It contains no business logic — only reading the `route` query parameter and `REQUEST_METHOD`, resolving `logs/`'s physical path via `Server.MapPath`, invoking `WscMvc.RequestContext` and `WscMvc.Application`, and writing the response.
- `Framework/RequestContext.wsc`, `Framework/Application.wsc`, and `Controllers/HomeController.wsc` never reference `Request`/`Response`/`Server`/`Session`. All data crosses the ASP-to-WSC and WSC-to-WSC boundaries as either VBScript scalars (strings) or our own `RequestContext` COM object (not an ASP intrinsic) — never an ASP host object. See `docs/DECISIONS.md` for why the original SPEC §15 open question about passing ASP intrinsics into a WSC never needed a direct experiment: the architecture never crosses that boundary by design.
- WSC public members are exposed as plain `<method>` entries backed by ordinary `Sub`/`Function` procedures, never `<property>`/`Property Get`. VBScript's `Property Get/Let/Set` requires a `Class...End Class` block and cannot appear at a WSC's top-level script scope — confirmed experimentally (see `docs/DECISIONS.md`), not assumed from general WSC documentation.
- Routing in M1/M2 is still a single hardcoded `If path = "/hello"` check inside `Application.Run`. This is intentionally minimal and will be replaced by the explicit allowlisted route table in M3 (`Router.wsc`); do not extend it ad hoc before that milestone.
- `Application.Run` is the single central point that decides expected (404, ordinary control flow) vs. unexpected (COM/method failure, 500) outcomes, and the single point that logs every outcome. `Default.asp` still independently guards its own three sequential calls (`RequestContext` creation, `Initialize`, `Application` creation, `Run`) since a WSC failing to even instantiate happens outside `Application.Run`'s reach.

## Per-request lifetime and diagnostics

- `RequestContext` and `Application` are both created fresh per request via `Server.CreateObject` in `Default.asp` and dropped (`Set ... = Nothing`) at the end of the page; neither is ever cached in ASP `Session`/`Application` scope, per SPEC §10.
- `RequestContext.Initialize` generates a correlation id from `Fix(Timer)` plus `Scripting.FileSystemObject.GetTempName()` — not `Randomize`/`Rnd()`, which was tried first and shown experimentally to collide when two contexts are created within the same clock tick (see `docs/DECISIONS.md`).
- `Application.LogOutcome` appends one line per request (timestamp, correlation id, method, path, status line, elapsed ms) to `logs/app.log`, guarded end-to-end by `On Error Resume Next` so a logging failure can never affect the HTTP response. Concurrent writers are serialized with a manual lock-file mutex (`logs/app.log.lock`, via `CreateTextFile(..., OverwriteExisting:=False)`) since no ASP intrinsic locking primitive (`Application.Lock`) is available to code that must not reference ASP intrinsics. The retry budget is deliberately short (see `docs/DECISIONS.md`): logging is explicitly best-effort and may drop lines under heavy concurrency without affecting correctness of the response.

## COM identity

| Component | ProgID | CLSID |
|---|---|---|
| `Framework/RequestContext.wsc` | `WscMvc.RequestContext` | `{1C36FA55-34DF-4974-94B9-D657389362B2}` |
| `Framework/Application.wsc` | `WscMvc.Application` | `{851C7763-1638-42FE-A166-BF3DD3A96A88}` |
| `Controllers/HomeController.wsc` | `WscMvc.HomeController` | `{87488446-60BE-4068-8368-0B709BB68F3F}` |

CLSIDs are fixed at creation and must never be recycled for a different component (AGENTS.md).
CLSIDs are fixed at creation and must never be recycled for a different component (AGENTS.md). `Application`'s public `Run` signature changed between M1 and M2 (added a leading `ctx` parameter) under the same CLSID; acceptable because this is active pre-release (v0.1) development with exactly one caller (`Default.asp`, updated in lockstep) — not a claim that live interface changes are safe for a published/external client.

## IIS site (test host: win2025test, 100.127.62.31)

- Site: `WscMvc`, binding `*:8090`, physical path `C:\Projects\wsc-mvc`.
- App pool: `WscMvc`, 64-bit, no managed code.
- `web.config` hides `Framework/`, `Controllers/`, `tests/`, `tools/`, `docs/` (path-segment based, anywhere in the tree) and denies `.wsc/.vbs/.ps1/.md` by extension.
- App pool: `WscMvc`, 64-bit, no managed code. Anonymous authentication identity: `IUSR`.
- `web.config` hides `Framework/`, `Controllers/`, `tests/`, `tools/`, `docs/`, `logs/` (path-segment based, anywhere in the tree) and denies `.wsc/.vbs/.ps1/.md` by extension.
- `logs/` has an explicit, scoped `icacls ... /grant "IIS_IUSRS:(OI)(CI)M"` so classic ASP (impersonating `IUSR` for anonymous requests) can write `app.log`. No other project directory grants `IUSR`/`IIS_IUSRS` write access — verified with a recursive `icacls /T` scan, see `docs/DECISIONS.md`.
- Default document is `Default.asp`; `/hello` is served via a rewrite rule, not the default document.

## Deferred to later milestones (do not implement early)

Per SPEC §3 non-goals and IMPLEMENTATION_PLAN M2+: request/response context object, central error mapping, explicit route table, HTML views/templates, ADODB, auth, logging. M1's error handling is intentionally local (`Default.asp` and `Application.wsc` each guard their own `CreateObject`/method-call boundary) rather than centralized.
Per SPEC §3 non-goals and IMPLEMENTATION_PLAN M3+: explicit route table, HTML views/templates, ADODB, auth. A more robust logging mechanism (if complete coverage under concurrent load is ever required) is deferred to M6 — see the concurrency finding in `docs/DECISIONS.md`.

+ 18
- 0
docs/DECISIONS.md Просмотреть файл

@@ -45,3 +45,21 @@ Used IIS `requestFiltering/hiddenSegments` (blocks any URL path containing `Fram
## Site/port allocation

New dedicated site `WscMvc`, app pool `WscMvc` (64-bit, no managed code), binding `*:8090`, physical path `C:\Projects\wsc-mvc`. Chosen to avoid the existing `*:80` and `*:8080` bindings already in use on this VM.

## M2 — Lifecycle, central error handling, correlation-safe diagnostics (2026-09-19)

Added `Framework/RequestContext.wsc` (`WscMvc.RequestContext`), a per-request, primitive-only data holder (path, HTTP method, a correlation id, a log directory, elapsed-time tracking). `Default.asp` creates and `Initialize`s one per request and passes it into `Application.Run(ctx, ...)` in place of the raw `pathInfo` string from M1. `Application.wsc` centralizes both the expected-vs-unexpected outcome decision (404 is expected control flow; a `CreateObject`/method-call failure is 500) and best-effort logging of every outcome (`logs/app.log`: timestamp, correlation id, method, path, status line, elapsed ms) in one place (`LogOutcome`), per SPEC §10/§13's M2 requirement. `logs/` was added to `web.config`'s `hiddenSegments` so it is never HTTP-reachable.

Three real defects were found and fixed while building this, all confirmed experimentally rather than assumed:

**1. `Property Get/Let/Set` cannot be used at the top level of a WSC `<script>` block.** First draft of `RequestContext.wsc` exposed `Path`/`HttpMethod`/`CorrelationId`/`LogDir` via `Property Get` procedures declared via `<property><get/></property>` in the `<public>` block. Registration failed with `regsvr32` exit code 5 (`DllRegisterServer` failed). Isolated with `GetObject("script:<path>.wsc")` from `cscript`, which surfaced the real error: VBScript error 1048, `"Must be defined inside a Class"`. VBScript only allows `Property Get/Let/Set` inside a `Class...End Class` block; a WSC's top-level script scope is not a class, regardless of what the WSC `<public>` XML declares. Fixed by exposing plain parameterless `Function`s (`Path()`, `HttpMethod()`, etc.) via `<method>` instead of `<property>` — the same pattern already proven working in `Application.wsc`/`HomeController.wsc`. Late-bound VBScript call sites (`ctx.Path`, no parens) work identically whether the target is a method or a property, so no caller code needed to change.

**2. `FormatNumber()` leaks a locale thousands-separator into generated ids.** The first correlation-id implementation built a value from `FormatNumber(Timer, 4)`; on this host's locale that produces a comma-grouped string (e.g. `32,188.0400`), so a correlation id came out containing a literal comma (`32,1880400-714275`) — harmless today but a latent bug for any future comma-delimited log/CSV consumer. Confirmed via a standalone `GetObject`-based probe before it ever reached a real component. Fixed by building the numeric parts with `Fix()`/integer arithmetic instead of `FormatNumber()`.

**3. `Randomize` + `Rnd()` collide when called twice inside the same clock tick.** After fixing (2), a WSH test creating two `RequestContext` instances back-to-back got the *same* correlation id both times. Root cause, confirmed experimentally: `Randomize` with no argument reseeds VBScript's RNG from the system timer; two calls within the same timer resolution window reseed to an identical state, so the immediately-following `Rnd()` returns the same first value both times. This is a genuine hazard for any correlation/nonce-style id generated this way in a tight loop (exactly the shape of "two requests arriving close together," which is the whole point of a correlation id). Fixed by dropping `Randomize`/`Rnd()` entirely in favor of `Scripting.FileSystemObject.GetTempName()`, confirmed experimentally to return a distinct value on every call in a tight loop with no dependency on `Randomize` state.

**4. Best-effort append-logging to one shared text file loses lines under concurrency, and a plain retry-the-open loop does not fix it.** With 8 genuinely concurrent `/hello` requests (confirmed genuinely concurrent via a control experiment: unique-per-request marker files with no shared-file contention all succeeded independently), a naive `OpenTextFile(path, ForAppending, Create:=True)` on every request lost roughly half its lines — not because the open call fails under contention (it mostly succeeds; `OpenTextFile` isn't exclusive), but because unsynchronized concurrent appends is a lost-update race. Retrying only the open call made this *worse*, not better (measured: down to 1 surviving line of 8), because it does nothing to stop the underlying race. Fixed with a manual mutex: `FileSystemObject.CreateTextFile(lockPath, OverwriteExisting:=False)` atomically fails with `Err.Number=58 "File already exists"` when another request already holds the lock file — confirmed correct/exclusive with a dedicated diagnostic harness, not assumed. The lock genuinely serializes the critical section (open `app.log`, write, close), but making *every* concurrent request eventually win requires a large retry budget: measured 300 retries (~330-360ms of blocking) needed for 8-way concurrency before all callers reliably see the lock come free. That much added latency on every request is a bad tradeoff for a best-effort diagnostic write, so the shipped retry budget is deliberately short (10 attempts, ~a few ms). **Accepted, documented consequence**: under moderate-to-heavy concurrent load, some `app.log` lines will legitimately be dropped; this never affects the HTTP response, which is correct and on-time in 100% of observed cases regardless of logging outcome. Revisit with a real logging mechanism (e.g. per-request-unique files aggregated out of band, or a proper OS-level named mutex via a small helper) in M6 if complete log coverage under load becomes an actual requirement — do not spend more effort on this in M2, it is explicitly a "safe diagnostic information" nice-to-have per SPEC §10, not a correctness requirement.

## Investigated and resolved: an inherited `IUSR:(F)` ACE appeared under `logs/`

While diagnosing the concurrency finding above, `icacls C:\Projects\wsc-mvc\logs` showed an inherited `NT AUTHORITY\IUSR:(I)(F)` (Full Control) entry that wasn't present as an explicit ACE on `C:\Projects\wsc-mvc` or `C:\Projects` themselves. Initially flagged as a possible SPEC §10 "no broad filesystem write privileges" violation (anonymous web identity with Full Control beyond what it needs). Investigated properly rather than left as a guess: a recursive `icacls C:\Projects\wsc-mvc /T` scan shows the `IUSR:(F)` ACE present **only** on `logs/` and files/folders created underneath it during testing (`app.log`, diagnostic marker files, etc.) — confirmed absent on `Framework/`, `Controllers/`, `Default.asp`, `web.config`, `tools/`, `tests/`. Both `C:\Projects` and `C:\Projects\wsc-mvc` carry an inherited `CREATOR OWNER:(I)(OI)(CI)(IO)(F)` ACE (the `(IO)` = inherit-only flag), which is standard NTFS behavior: it doesn't grant CREATOR OWNER anything on the folder itself, but materializes into a concrete Full Control ACE for whichever security principal actually creates each new child file/folder underneath. Since IUSR (impersonated by classic ASP for anonymous requests, per this site's `anonymousAuthentication` config) was the one creating files under `logs/` during testing, it received Full Control on exactly those files it created there — nowhere else. **Resolved, not a defect**: this is expected NTFS ownership semantics, correctly scoped to only the dynamically-created log tree (which is already denied over HTTP via `hiddenSegments`), not a broad grant across the source tree. No remediation needed; no M6 follow-up required for this specific concern.

+ 60
- 0
docs/TEST-RESULTS.md Просмотреть файл

@@ -92,3 +92,63 @@ Result: **PASS** — both returned `200`, both bodies exactly `Hello from WSC-MV
## M1 gate status: **PASS**

All SPEC §14 acceptance criteria for M1 were run on real Windows/IIS (not inferred) and passed, including one real defect found and fixed during testing (unregistration). Proceeding to M2 (lifecycle/error-handling generalization) is unblocked.

## M2 — Lifecycle, central error handling, correlation-safe diagnostics

### WSH component tests (`RequestContext` + `Application` with `ctx`)

Command:
```
cscript //nologo C:\Projects\wsc-mvc\tests\Test-Components.vbs
```
Result: **PASS** (after fixing three real defects found while getting here — see `docs/DECISIONS.md`: `Property Get` outside a `Class` block failing registration; `FormatNumber` leaking a locale comma into correlation ids; `Randomize`/`Rnd()` colliding within the same clock tick):
```
PASS: RequestContext.Path
PASS: RequestContext.HttpMethod
PASS: RequestContext.CorrelationId non-empty (32810-radD62B0)
PASS: RequestContext.ElapsedMs non-negative (0)
PASS: two RequestContext instances have distinct CorrelationIds
PASS: Application.Run(/hello) statusLine
PASS: Application.Run(/hello) contentType
PASS: Application.Run(/hello) body
PASS: Application.Run(unknown route) statusLine
PASS: app.log contains both 200 OK and 404 Not Found outcomes
RESULT: ALL PASS
```

### HTTP integration test (unchanged contract from the client's point of view)

Command: `powershell -File tests\Test-Http.ps1 -BaseUrl http://localhost:8090` — **PASS**, identical output to M1 (the `ctx`-based rewrite is entirely internal to `Application.wsc`/`Default.asp`; the HTTP contract for `/hello` and denied `.wsc` access is unchanged).

### Correlation-safe diagnostics (logging)

Verified real HTTP requests produce correct `logs/app.log` entries (timestamp, correlation id, method, path, status, elapsed ms), e.g.:
```
9/19/2026 8:57:05 AM | 322254727-607479 | GET | /hello | 200 OK | 6ms
```
`logs/` is denied over HTTP (`GET /logs/app.log` -> 404, same `hiddenSegments` mechanism as other private directories). **PASS**

### Concurrency (real, load-bearing this time)

- 8 genuinely concurrent `/hello` requests (bash `&`/`wait`): **all 8 returned `200 OK` with the correct body, every time, across every run in this milestone.** This is the actual M2 gate requirement ("repeated/concurrent requests... behave predictably") and it holds unconditionally.
- Confirmed the 8 requests really do execute concurrently (not serialized by IIS/ASP) using a control experiment: 8 concurrent requests to a throwaway diagnostic page writing unique-per-request marker files (no shared-file contention possible) — 5 of 8 succeeded independently before the diagnostic page itself was deleted (the other 3 hit an unguarded race in the throwaway diagnostic script's own `CreateFolder` call, not the real app).
- `logs/app.log` line count under 8-way concurrency: as few as 1-4 of 8 lines survive, depending on run. This is an accepted, documented tradeoff (see `docs/DECISIONS.md`) — the retry budget for the log-file mutex is kept deliberately short so logging contention never adds meaningful latency to the HTTP response. **The response correctness gate is unaffected**; only the completeness of the best-effort diagnostic log is. Not treated as a FAIL: SPEC §10 calls this "safe diagnostic information," not a correctness requirement.

### Reversible unregistration (extended to three components)

Command sequence identical to M1, now covering `RequestContext.wsc` too:
```
powershell -File tools\Register-Components.ps1
powershell -File tools\Unregister-Components.ps1 # confirmed all 3 ProgID/CLSID pairs removed via registry inspection
powershell -File tools\Register-Components.ps1
```
Result: **PASS** — `/hello` returns `500` while unregistered and `200` after re-registering, for all three components together.

## Not yet run / out of scope for M2

- A logging mechanism with guaranteed no-loss-under-load delivery — explicitly deferred to M6 (see `docs/DECISIONS.md`).
- Formal 400/405 method-not-allowed handling — still waiting on M3's route table.

## M2 gate status: **PASS**

The SPEC §13 M2 gate ("repeated/concurrent requests and failure cases behave predictably") was run on real Windows/IIS and holds unconditionally for HTTP response correctness. Four real defects were found and fixed while building this milestone (WSC property-syntax limitation, a locale-formatting bug, a `Randomize` collision, and a naive concurrent-logging approach that made things worse before a working lock-file mutex was verified) — see `docs/DECISIONS.md` for full detail on each. Proceeding to M3 (routing) is unblocked.

+ 102
- 19
tests/Test-Components.vbs Просмотреть файл

@@ -1,25 +1,77 @@
Option Explicit

Dim app, ctrl, statusLine, contentType, body, pass
Dim fso, logDir, pass
pass = True

Set fso = CreateObject("Scripting.FileSystemObject")
logDir = fso.GetParentFolderName(WScript.ScriptFullName) & "\test-logs"
If fso.FolderExists(logDir) Then
fso.DeleteFolder logDir, True
End If

Function NewContext(path, httpMethod)
Dim ctx
Set ctx = CreateObject("WscMvc.RequestContext")
ctx.Initialize path, httpMethod, logDir
Set NewContext = ctx
End Function

Sub CheckEqual(actual, expected, label)
If actual = expected Then
WScript.Echo "PASS: " & label
Else
WScript.Echo "FAIL: " & label & " -> expected [" & expected & "] got [" & actual & "]"
pass = False
End If
End Sub

' --- RequestContext contract ---
Dim ctx1
On Error Resume Next
Set app = CreateObject("WscMvc.Application")
Set ctx1 = NewContext("/hello", "GET")
If Err.Number <> 0 Then
WScript.Echo "FAIL: could not create WscMvc.Application - " & Err.Description
WScript.Echo "FAIL: could not create/initialize WscMvc.RequestContext - " & Err.Description
pass = False
Err.Clear
End If
On Error Goto 0

If pass Then
statusLine = ""
contentType = ""
body = ""
CheckEqual ctx1.Path, "/hello", "RequestContext.Path"
CheckEqual ctx1.HttpMethod, "GET", "RequestContext.HttpMethod"
If Len(ctx1.CorrelationId) > 0 Then
WScript.Echo "PASS: RequestContext.CorrelationId non-empty (" & ctx1.CorrelationId & ")"
Else
WScript.Echo "FAIL: RequestContext.CorrelationId empty"
pass = False
End If
If ctx1.ElapsedMs() >= 0 Then
WScript.Echo "PASS: RequestContext.ElapsedMs non-negative (" & ctx1.ElapsedMs() & ")"
Else
WScript.Echo "FAIL: RequestContext.ElapsedMs negative"
pass = False
End If
End If

' --- Two independent contexts must not share correlation IDs or state ---
Dim ctx2
If pass Then
Set ctx2 = NewContext("/does-not-exist", "GET")
If ctx1.CorrelationId <> ctx2.CorrelationId Then
WScript.Echo "PASS: two RequestContext instances have distinct CorrelationIds"
Else
WScript.Echo "FAIL: two RequestContext instances produced the same CorrelationId - " & ctx1.CorrelationId
pass = False
End If
End If

' --- Application.Run happy path via ctx ---
Dim app, statusLine, contentType, body
If pass Then
On Error Resume Next
app.Run "/hello", statusLine, contentType, body
Set app = CreateObject("WscMvc.Application")
If Err.Number <> 0 Then
WScript.Echo "FAIL: Application.Run raised error on /hello - " & Err.Description
WScript.Echo "FAIL: could not create WscMvc.Application - " & Err.Description
pass = False
Err.Clear
End If
@@ -27,20 +79,28 @@ If pass Then
End If

If pass Then
If statusLine = "200 OK" And contentType = "text/html; charset=utf-8" And body = "Hello from WSC-MVC!" Then
WScript.Echo "PASS: /hello -> " & statusLine & " | " & contentType & " | " & body
Else
WScript.Echo "FAIL: unexpected /hello result -> [" & statusLine & "] [" & contentType & "] [" & body & "]"
statusLine = "" : contentType = "" : body = ""
On Error Resume Next
app.Run ctx1, statusLine, contentType, body
If Err.Number <> 0 Then
WScript.Echo "FAIL: Application.Run raised error on /hello - " & Err.Description
pass = False
Err.Clear
End If
On Error Goto 0
End If

If pass Then
statusLine = ""
contentType = ""
body = ""
CheckEqual statusLine, "200 OK", "Application.Run(/hello) statusLine"
CheckEqual contentType, "text/html; charset=utf-8", "Application.Run(/hello) contentType"
CheckEqual body, "Hello from WSC-MVC!", "Application.Run(/hello) body"
End If

' --- Application.Run unknown route via ctx (expected 404, not an error) ---
If pass Then
statusLine = "" : contentType = "" : body = ""
On Error Resume Next
app.Run "/does-not-exist", statusLine, contentType, body
app.Run ctx2, statusLine, contentType, body
If Err.Number <> 0 Then
WScript.Echo "FAIL: Application.Run raised error on unknown route - " & Err.Description
pass = False
@@ -50,15 +110,38 @@ If pass Then
End If

If pass Then
If statusLine = "404 Not Found" Then
WScript.Echo "PASS: unknown route -> " & statusLine
CheckEqual statusLine, "404 Not Found", "Application.Run(unknown route) statusLine"
End If

' --- Logging: best-effort log file was written with both outcomes ---
If pass Then
Dim logPath, logContent
logPath = logDir & "\app.log"
If fso.FileExists(logPath) Then
Dim logStream
Set logStream = fso.OpenTextFile(logPath, 1)
logContent = logStream.ReadAll
logStream.Close
If InStr(logContent, "200 OK") > 0 And InStr(logContent, "404 Not Found") > 0 Then
WScript.Echo "PASS: app.log contains both 200 OK and 404 Not Found outcomes"
Else
WScript.Echo "FAIL: app.log missing expected outcomes -> " & logContent
pass = False
End If
Else
WScript.Echo "FAIL: unexpected unknown-route result -> [" & statusLine & "]"
WScript.Echo "FAIL: app.log was not created at " & logPath
pass = False
End If
End If

Set app = Nothing
Set ctx1 = Nothing
Set ctx2 = Nothing

If fso.FolderExists(logDir) Then
fso.DeleteFolder logDir, True
End If
Set fso = Nothing

If pass Then
WScript.Echo "RESULT: ALL PASS"


+ 1
- 0
tools/Register-Components.ps1 Просмотреть файл

@@ -8,6 +8,7 @@ if (-not $ProjectRoot) {
}

$components = @(
(Join-Path $ProjectRoot 'Framework\RequestContext.wsc'),
(Join-Path $ProjectRoot 'Framework\Application.wsc'),
(Join-Path $ProjectRoot 'Controllers\HomeController.wsc')
)


+ 2
- 1
tools/Unregister-Components.ps1 Просмотреть файл

@@ -16,7 +16,8 @@ if (-not $ProjectRoot) {

$components = @(
@{ Path = (Join-Path $ProjectRoot 'Controllers\HomeController.wsc'); ProgId = 'WscMvc.HomeController'; ClassId = '{87488446-60BE-4068-8368-0B709BB68F3F}' },
@{ Path = (Join-Path $ProjectRoot 'Framework\Application.wsc'); ProgId = 'WscMvc.Application'; ClassId = '{851C7763-1638-42FE-A166-BF3DD3A96A88}' }
@{ Path = (Join-Path $ProjectRoot 'Framework\Application.wsc'); ProgId = 'WscMvc.Application'; ClassId = '{851C7763-1638-42FE-A166-BF3DD3A96A88}' },
@{ Path = (Join-Path $ProjectRoot 'Framework\RequestContext.wsc'); ProgId = 'WscMvc.RequestContext'; ClassId = '{1C36FA55-34DF-4974-94B9-D657389362B2}' }
)

function Remove-ProjectComponent {


+ 1
- 0
web.config Просмотреть файл

@@ -9,6 +9,7 @@
<add segment="tests" />
<add segment="tools" />
<add segment="docs" />
<add segment="logs" />
</hiddenSegments>
<fileExtensions>
<add fileExtension=".wsc" allowed="false" />


Загрузка…
Отмена
Сохранить

Powered by TurnKey Linux.