diff --git a/.gitignore b/.gitignore new file mode 100644 index 0000000..333c1e9 --- /dev/null +++ b/.gitignore @@ -0,0 +1 @@ +logs/ diff --git a/Default.asp b/Default.asp index 571c0f7..0c2eed8 100644 --- a/Default.asp +++ b/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 %> diff --git a/Framework/Application.wsc b/Framework/Application.wsc index 128e9e5..ab1758b 100644 --- a/Framework/Application.wsc +++ b/Framework/Application.wsc @@ -10,7 +10,7 @@ - + @@ -21,12 +21,16 @@ 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 ]]> diff --git a/Framework/RequestContext.wsc b/Framework/RequestContext.wsc new file mode 100644 index 0000000..319c29c --- /dev/null +++ b/Framework/RequestContext.wsc @@ -0,0 +1,92 @@ + + + + + + + + + + + + + + + + + + + + + diff --git a/IMPLEMENTATION_PLAN.md b/IMPLEMENTATION_PLAN.md index 8173edb..28ffc65 100644 --- a/IMPLEMENTATION_PLAN.md +++ b/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. diff --git a/docs/ARCHITECTURE.md b/docs/ARCHITECTURE.md index 50c783a..21f9e89 100644 --- a/docs/ARCHITECTURE.md +++ b/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 `` entries backed by ordinary `Sub`/`Function` procedures, never ``/`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`. diff --git a/docs/DECISIONS.md b/docs/DECISIONS.md index e0279bb..2a6c11e 100644 --- a/docs/DECISIONS.md +++ b/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 `