@@ -26,6 +26,7 @@ import (
2626 "path/filepath"
2727 "runtime"
2828 "strconv"
29+ "strings"
2930 "sync"
3031 "testing"
3132 "time"
@@ -89,10 +90,17 @@ func downloadLegacyCLI(t *testing.T) string {
8990// Local app
9091// ---------------------------------------------------------------------------
9192
93+ // deliveryIDHeader tags every request these tests send with a value unique to
94+ // that send. Hookdeck forwards it to the local app, so a step waits for its own
95+ // delivery rather than whatever arrives next, and a failure can find the
96+ // request and its event in the API.
97+ const deliveryIDHeader = "X-Acceptance-Delivery-Id"
98+
9299// receivedRequest is one request as the local app saw it. Files holds what the
93100// app wrote to disk: the raw body for single-file requests, or every file part
94101// of a multipart form, keyed by form field name.
95102type receivedRequest struct {
103+ deliveryID string
96104 contentType string
97105 eventID string
98106 attemptCount int
@@ -126,6 +134,7 @@ func startLocalApp(t *testing.T) *localApp {
126134 app .mu .Unlock ()
127135
128136 req := receivedRequest {
137+ deliveryID : r .Header .Get (deliveryIDHeader ),
129138 contentType : r .Header .Get ("Content-Type" ),
130139 eventID : r .Header .Get ("X-Hookdeck-EventID" ),
131140 files : map [string ]string {},
@@ -184,17 +193,25 @@ func (a *localApp) setStatus(status func(n int) int) {
184193 a .status = status
185194}
186195
187- func (a * localApp ) next (t * testing.T , within time.Duration , outputs ... * syncBuffer ) receivedRequest {
196+ // next waits for the delivery of the request sent with deliveryID. A delivery
197+ // of an earlier step's request is logged and skipped: one arriving late used
198+ // to be taken as the next step's, so a slow first delivery failed the step
199+ // after it instead. On timeout it reports how far the request got.
200+ func (a * localApp ) next (t * testing.T , s binaryListenSetup , deliveryID string , within time.Duration , l listenOutput ) receivedRequest {
188201 t .Helper ()
189- select {
190- case r := <- a .received :
191- return r
192- case <- time .After (within ):
193- for _ , o := range outputs {
194- t .Logf ("listen output: %s" , o .String ())
202+ timeout := time .After (within )
203+ for {
204+ select {
205+ case r := <- a .received :
206+ if r .deliveryID == deliveryID {
207+ return r
208+ }
209+ t .Logf ("local app: skipping a delivery of %q while waiting for %q" , r .deliveryID , deliveryID )
210+ case <- timeout :
211+ l .log (t )
212+ t .Fatalf ("no request reached the local app within %s.\n %s" , within , s .explainMissingDelivery (t , deliveryID ))
213+ return receivedRequest {}
195214 }
196- t .Fatalf ("no request reached the local app within %s; if the event failed with CLI_BINARY_UNSUPPORTED, the server does not deliver binary bodies to this CLI" , within )
197- return receivedRequest {}
198215 }
199216}
200217
@@ -348,6 +365,7 @@ func assertSavedFile(t *testing.T, path string, want fixture) {
348365type binaryListenSetup struct {
349366 cli * CLIRunner
350367 sourceName string
368+ sourceID string
351369 sourceURL string
352370 connID string
353371}
@@ -369,38 +387,163 @@ func newBinaryListenSetup(t *testing.T, prefix string) binaryListenSetup {
369387 "--destination-cli-path" , "/" ,
370388 ))
371389 require .NotEmpty (t , conn .ID )
372- t .Cleanup (func () { deleteConnection (t , cli , conn .ID ) })
390+ // No cleanup of its own: listen's cleanup deletes the connection by source
391+ // name, and a second delete here only logged a 410 warning into every
392+ // failure's output.
373393
374394 var src Source
375395 require .NoError (t , cli .RunJSON (& src , "gateway" , "source" , "get" , conn .Source .ID ))
376396 require .NotEmpty (t , src .URL )
377- return binaryListenSetup {cli : cli , sourceName : sourceName , sourceURL : src .URL , connID : conn .ID }
397+ return binaryListenSetup {cli : cli , sourceName : sourceName , sourceID : conn .Source .ID , sourceURL : src .URL , connID : conn .ID }
398+ }
399+
400+ // listenOutput is a running `hookdeck listen` started by these tests.
401+ type listenOutput struct {
402+ stdout , stderr * syncBuffer
403+ done chan error
404+ }
405+
406+ // listenReadyLine is what listen prints in compact mode once its websocket is
407+ // connected. Both this CLI and v3.0.3 print it.
408+ const listenReadyLine = "Connected. Waiting for events..."
409+
410+ // startBinaryListen runs `listen` for the setup's source, forwarding to port,
411+ // from binary or, when binary is empty, from a fresh build of this CLI. Debug
412+ // logging is on so a failure can show whether any message reached the
413+ // session's websocket.
414+ func startBinaryListen (t * testing.T , cli * CLIRunner , binary , port , sourceName string ) listenOutput {
415+ t .Helper ()
416+ args := []string {"listen" , port , sourceName , "--output" , "compact" , "--log-level" , "debug" }
417+ var l listenOutput
418+ if binary == "" {
419+ _ , l .stdout , l .stderr , l .done = startListenCapturingOutput (t , cli , args ... )
420+ } else {
421+ _ , l .stdout , l .stderr , l .done = startListenBinaryCapturingOutput (t , cli , binary , args ... )
422+ }
423+ return l
378424}
379425
380- // waitForTunnel gives listen time to connect and fails fast if it exited.
381- func waitForTunnel (t * testing.T , done chan error , outputs ... * syncBuffer ) {
426+ // waitReady waits for listen to report its websocket connected, rather than
427+ // sleeping a fixed time, and fails fast if listen exits first.
428+ func (l listenOutput ) waitReady (t * testing.T ) {
382429 t .Helper ()
383- t .Log ("Waiting 12 seconds for the tunnel to connect..." )
384- time .Sleep (12 * time .Second )
385- select {
386- case err := <- done :
387- for _ , o := range outputs {
388- t .Logf ("listen output: %s" , o .String ())
430+ const within = 60 * time .Second
431+ deadline := time .Now ().Add (within )
432+ for ! strings .Contains (l .stdout .String (), listenReadyLine ) {
433+ select {
434+ case err := <- l .done :
435+ l .log (t )
436+ t .Fatalf ("listen exited before connecting: %v" , err )
437+ case <- time .After (100 * time .Millisecond ):
438+ }
439+ if time .Now ().After (deadline ) {
440+ l .log (t )
441+ t .Fatalf ("listen did not print %q within %s" , listenReadyLine , within )
442+ }
443+ }
444+ }
445+
446+ // log writes listen's stdout, and the lines of its debug log that say what
447+ // happened on the websocket: connects, closes, and every incoming message.
448+ // The rest of the debug log is API traffic and would bury those lines.
449+ func (l listenOutput ) log (t * testing.T ) {
450+ t .Helper ()
451+ t .Logf ("listen stdout:\n %s" , l .stdout .String ())
452+ var lines []string
453+ for _ , line := range strings .Split (l .stderr .String (), "\n " ) {
454+ if ! strings .Contains (line , "prefix=websocket." ) && ! strings .Contains (line , "level=error" ) && ! strings .Contains (line , "level=warn" ) {
455+ continue
389456 }
390- t .Fatalf ("listen exited before forwarding anything: %v" , err )
391- default :
457+ if len (line ) > 300 {
458+ line = line [:300 ] + "..."
459+ }
460+ lines = append (lines , line )
392461 }
462+ t .Logf ("listen websocket log:\n %s" , strings .Join (lines , "\n " ))
393463}
394464
395- // postRaw sends body to a source URL with the given Content-Type, unmodified.
396- func postRaw (t * testing.T , sourceURL , contentType string , body []byte ) {
465+ // postRaw sends body to the setup's source URL with the given Content-Type,
466+ // unmodified, and returns the delivery id it tagged the request with.
467+ func (s binaryListenSetup ) postRaw (t * testing.T , contentType string , body []byte ) string {
397468 t .Helper ()
469+ deliveryID := fmt .Sprintf ("%s-%d" , s .sourceName , time .Now ().UnixNano ())
470+ req , err := http .NewRequest (http .MethodPost , s .sourceURL , bytes .NewReader (body ))
471+ require .NoError (t , err )
472+ req .Header .Set ("Content-Type" , contentType )
473+ req .Header .Set (deliveryIDHeader , deliveryID )
398474 client := & http.Client {Timeout : 10 * time .Second }
399- resp , err := client .Post ( sourceURL , contentType , bytes . NewReader ( body ) )
475+ resp , err := client .Do ( req )
400476 require .NoError (t , err , "POST to source URL failed" )
401477 defer resp .Body .Close ()
402478 require .True (t , resp .StatusCode >= 200 && resp .StatusCode < 300 ,
403479 "POST to source URL returned %d" , resp .StatusCode )
480+ return deliveryID
481+ }
482+
483+ // explainMissingDelivery says how far the request tagged deliveryID got, as
484+ // the API reports it: whether the source recorded it, whether an event was
485+ // created for a CLI, and whether that event was ever attempted. Together with
486+ // the websocket log it separates "never sent to this listen session" from
487+ // "sent, but not forwarded by the CLI".
488+ func (s binaryListenSetup ) explainMissingDelivery (t * testing.T , deliveryID string ) string {
489+ t .Helper ()
490+ var requests struct {
491+ Models []struct {
492+ ID string `json:"id"`
493+ EventsCount int `json:"events_count"`
494+ CLIEventsCount int `json:"cli_events_count"`
495+ IgnoredCount int `json:"ignored_count"`
496+ RejectionCause any `json:"rejection_cause"`
497+ } `json:"models"`
498+ }
499+ // Search lags a few seconds behind ingestion, so a request sent moments ago
500+ // can be missing from it; give it a short while before saying so.
501+ for i := 0 ; i < 10 ; i ++ {
502+ if err := s .cli .RunJSON (& requests , "gateway" , "request" , "list" , "--source-id" , s .sourceID , "--search-term" , deliveryID ); err != nil {
503+ return fmt .Sprintf ("Could not look up the request: %v" , err )
504+ }
505+ if len (requests .Models ) > 0 {
506+ break
507+ }
508+ time .Sleep (2 * time .Second )
509+ }
510+ if len (requests .Models ) == 0 {
511+ return fmt .Sprintf ("Source %s has no request tagged %s=%s." , s .sourceID , deliveryIDHeader , deliveryID )
512+ }
513+ r := requests .Models [0 ]
514+ report := []string {fmt .Sprintf ("Request %s: %d event(s), %d CLI event(s), %d ignored, rejection cause %v." ,
515+ r .ID , r .EventsCount , r .CLIEventsCount , r .IgnoredCount , r .RejectionCause )}
516+
517+ var events struct {
518+ Models []struct {
519+ ID string `json:"id"`
520+ CLIID string `json:"cli_id"`
521+ Status string `json:"status"`
522+ Attempts int `json:"attempts"`
523+ ErrorCode string `json:"error_code"`
524+ } `json:"models"`
525+ }
526+ if err := s .cli .RunJSON (& events , "gateway" , "event" , "list" , "--connection-id" , s .connID , "--search-term" , deliveryID ); err != nil {
527+ return strings .Join (append (report , fmt .Sprintf ("Could not look up its events: %v" , err )), "\n " )
528+ }
529+ if len (events .Models ) == 0 {
530+ report = append (report , "No event on connection " + s .connID + " carries this request." )
531+ }
532+ neverAttempted := false
533+ for _ , e := range events .Models {
534+ report = append (report , fmt .Sprintf ("Event %s for CLI %s: status %s, %d attempt(s), error code %q." ,
535+ e .ID , e .CLIID , e .Status , e .Attempts , e .ErrorCode ))
536+ if e .Attempts == 0 && (e .Status == "QUEUED" || e .Status == "SCHEDULED" ) {
537+ neverAttempted = true
538+ }
539+ if e .ErrorCode == "CLI_BINARY_UNSUPPORTED" {
540+ report = append (report , "CLI_BINARY_UNSUPPORTED: the server does not deliver binary bodies to this CLI." )
541+ }
542+ }
543+ if neverAttempted {
544+ report = append (report , "The event was created for a CLI but never attempted, so nothing was sent to the listen session: the delivery stopped before it reached the CLI." )
545+ }
546+ return strings .Join (report , "\n " )
404547}
405548
406549// ---------------------------------------------------------------------------
@@ -418,15 +561,15 @@ func TestListenForwardsBinaryFilesThatTheAppCanSave(t *testing.T) {
418561
419562 s := newBinaryListenSetup (t , "test-bin" )
420563 app := startLocalApp (t )
421- _ , stdout , stderr , done := startListenCapturingOutput (t , s .cli , "listen " , app .port , s .sourceName , "--output" , "compact" )
422- waitForTunnel ( t , done , stdout , stderr )
564+ listen := startBinaryListen (t , s .cli , "" , app .port , s .sourceName )
565+ listen . waitReady ( t )
423566
424567 // Raw bodies: the content types ingestion stores as binary.
425568 for _ , f := range []fixture {allBytesFixture (), pngFixture (t ), jpegFixture (t ), pdfFixture ()} {
426569 f := f
427570 t .Run ("raw " + f .contentType , func (t * testing.T ) {
428- postRaw ( t , s . sourceURL , f .contentType , f .data )
429- got := app .next (t , 45 * time .Second , stdout , stderr )
571+ id := s . postRaw ( t , f .contentType , f .data )
572+ got := app .next (t , s , id , 45 * time .Second , listen )
430573 assert .Equal (t , f .contentType , got .contentType , "original Content-Type must be forwarded" )
431574 assertSavedFile (t , got .files ["body" ], f )
432575 })
@@ -436,8 +579,8 @@ func TestListenForwardsBinaryFilesThatTheAppCanSave(t *testing.T) {
436579 files := []fixture {pngFixture (t ), wavFixture (), allBytesFixture ()}
437580 contentType , body := multipartUpload (t , files ... )
438581
439- postRaw ( t , s . sourceURL , contentType , body )
440- got := app .next (t , 45 * time .Second , stdout , stderr )
582+ id := s . postRaw ( t , contentType , body )
583+ got := app .next (t , s , id , 45 * time .Second , listen )
441584
442585 assert .Equal (t , contentType , got .contentType , "boundary travels in the original Content-Type" )
443586 require .Len (t , got .files , len (files ), "the app should save every file part" )
@@ -463,20 +606,21 @@ func TestListenRetriesBinaryBodyByteExact(t *testing.T) {
463606 }
464607 return http .StatusOK
465608 })
466- _ , stdout , stderr , done := startListenCapturingOutput (t , s .cli , "listen " , app .port , s .sourceName , "--output" , "compact" )
467- waitForTunnel ( t , done , stdout , stderr )
609+ listen := startBinaryListen (t , s .cli , "" , app .port , s .sourceName )
610+ listen . waitReady ( t )
468611
469612 f := pngFixture (t )
470- postRaw ( t , s . sourceURL , f .contentType , f .data )
613+ id := s . postRaw ( t , f .contentType , f .data )
471614
472- first := app .next (t , 45 * time .Second , stdout , stderr )
615+ first := app .next (t , s , id , 45 * time .Second , listen )
473616 require .NotEmpty (t , first .eventID , "delivery should carry X-Hookdeck-EventID" )
474617 assert .Equal (t , 1 , first .attemptCount )
475618 assertSavedFile (t , first .files ["body" ], f )
476619
477620 s .cli .RunExpectSuccess ("gateway" , "event" , "retry" , first .eventID )
478621
479- second := app .next (t , 45 * time .Second , stdout , stderr )
622+ // The retry delivers the same request, so it carries the same delivery id.
623+ second := app .next (t , s , id , 45 * time .Second , listen )
480624 assert .Equal (t , first .eventID , second .eventID , "the retry should deliver the same event" )
481625 assert .Equal (t , 2 , second .attemptCount )
482626 assert .Equal (t , f .contentType , second .contentType )
@@ -498,16 +642,16 @@ func TestListenBinaryWithOldAndNewCLIListening(t *testing.T) {
498642 legacyCLI := newSeparateCLIClient (t , s .cli )
499643 newApp := startLocalApp (t )
500644 oldApp := startLocalApp (t )
501- _ , newOut , newErr , newDone := startListenCapturingOutput (t , s .cli , "listen " , newApp .port , s .sourceName , "--output" , "compact" )
502- _ , oldOut , oldErr , oldDone := startListenBinaryCapturingOutput (t , legacyCLI , legacyBinary , "listen" , oldApp .port , s .sourceName , "--output" , "compact" )
503- waitForTunnel ( t , newDone , newOut , newErr )
504- waitForTunnel ( t , oldDone , oldOut , oldErr )
645+ newListen := startBinaryListen (t , s .cli , "" , newApp .port , s .sourceName )
646+ oldListen := startBinaryListen (t , legacyCLI , legacyBinary , oldApp .port , s .sourceName )
647+ newListen . waitReady ( t )
648+ oldListen . waitReady ( t )
505649
506650 t .Run ("raw image" , func (t * testing.T ) {
507651 f := pngFixture (t )
508- postRaw ( t , s . sourceURL , f .contentType , f .data )
652+ id := s . postRaw ( t , f .contentType , f .data )
509653
510- got := newApp .next (t , 45 * time .Second , newOut , newErr )
654+ got := newApp .next (t , s , id , 45 * time .Second , newListen )
511655 assertSavedFile (t , got .files ["body" ], f )
512656 oldApp .expectNothing (t , 20 * time .Second )
513657
@@ -517,16 +661,16 @@ func TestListenBinaryWithOldAndNewCLIListening(t *testing.T) {
517661 t .Run ("multipart upload" , func (t * testing.T ) {
518662 files := []fixture {pngFixture (t ), wavFixture ()}
519663 contentType , body := multipartUpload (t , files ... )
520- postRaw ( t , s . sourceURL , contentType , body )
664+ id := s . postRaw ( t , contentType , body )
521665
522- got := newApp .next (t , 45 * time .Second , newOut , newErr )
666+ got := newApp .next (t , s , id , 45 * time .Second , newListen )
523667 for i , f := range files {
524668 assertSavedFile (t , got .files [fmt .Sprintf ("file%d" , i )], f )
525669 }
526670
527671 // The old CLI still gets the upload, decoded as UTF-8 text as before
528672 // multipart moved to binary, so its file parts are not byte-exact.
529- legacy := oldApp .next (t , 45 * time .Second , oldOut , oldErr )
673+ legacy := oldApp .next (t , s , id , 45 * time .Second , oldListen )
530674 assert .Equal (t , contentType , legacy .contentType )
531675 legacyPNG , err := os .ReadFile (legacy .files ["file0" ])
532676 require .NoError (t , err )
0 commit comments