@@ -12,6 +12,16 @@ import {
1212import { getRegistries } from '../../src/storage/registries.js' ;
1313import { getOrCreateUserForToken } from '../../src/services/users.js' ;
1414
15+ /** The per-line timestamp prefix from the platform log format (api.md). */
16+ const LINE_STAMP = / ^ \d { 4 } - \d { 2 } - \d { 2 } T \d { 2 } : \d { 2 } : \d { 2 } \. \d { 3 } Z / ;
17+
18+ function stripStamps ( log : string ) : string {
19+ return log
20+ . split ( '\n' )
21+ . map ( ( line ) => line . replace ( LINE_STAMP , '' ) )
22+ . join ( '\n' ) ;
23+ }
24+
1525/** Polls `check()` until it returns true or `timeoutMs` elapses, rather than a fixed sleep - keeps the
1626 * disconnect test fast on the happy path and still deterministic if cleanup is ever slow. */
1727async function waitUntil ( check : ( ) => boolean , timeoutMs = 2000 ) : Promise < void > {
@@ -195,7 +205,7 @@ describe('log streaming', () => {
195205 await second ;
196206 spy . mockRestore ( ) ;
197207
198- expect ( await getFullLog ( jobId ) ) . toBe ( 'line1\nline2\n' ) ;
208+ expect ( stripStamps ( await getFullLog ( jobId ) ) ) . toBe ( 'line1\nline2\n' ) ;
199209 } ) ;
200210
201211 it ( 'getFullLog never returns a torn read while a flush for the same id is in flight (regression for the reader-vs-writer race)' , async ( ) => {
@@ -232,7 +242,7 @@ describe('log streaming', () => {
232242 const result = await read ;
233243 spy . mockRestore ( ) ;
234244
235- expect ( result ) . toBe ( 'first chunk\n' ) ;
245+ expect ( stripStamps ( result ) ) . toBe ( 'first chunk\n' ) ;
236246 } ) ;
237247
238248 it ( "flushAllLogs persists every live log's buffered content (regression for a lost trailing chunk on graceful shutdown)" , async ( ) => {
@@ -248,8 +258,8 @@ describe('log streaming', () => {
248258
249259 await flushAllLogs ( ) ;
250260
251- expect ( await getRegistries ( ) . logs . getValue ( jobId1 ) ) . toBe ( 'alpha\n' ) ;
252- expect ( await getRegistries ( ) . logs . getValue ( jobId2 ) ) . toBe ( 'beta\n' ) ;
261+ expect ( stripStamps ( ( await getRegistries ( ) . logs . getValue ( jobId1 ) ) ?? '' ) ) . toBe ( 'alpha\n' ) ;
262+ expect ( stripStamps ( ( await getRegistries ( ) . logs . getValue ( jobId2 ) ) ?? '' ) ) . toBe ( 'beta\n' ) ;
253263 } ) ;
254264
255265 it ( 'a stream closes when the persisted record turns terminal even if markLogTerminal is never called (regression: aborted in the READY window)' , async ( ) => {
@@ -401,7 +411,7 @@ describe('log streaming', () => {
401411
402412 const reader = res . body ! . getReader ( ) ;
403413 const { value } = await reader . read ( ) ;
404- expect ( Buffer . from ( value ! ) . toString ( ) ) . toBe ( 'line 1\n' ) ;
414+ expect ( stripStamps ( Buffer . from ( value ! ) . toString ( ) ) ) . toBe ( 'line 1\n' ) ;
405415
406416 // The initial response is a single `res.status(200).send(soFar)`, never `res.write` + a
407417 // held-open connection, so `subscribeLog` is never called - checked immediately after the first
@@ -444,10 +454,91 @@ describe('log streaming', () => {
444454
445455 const reader = res . body ! . getReader ( ) ;
446456 const { value } = await reader . read ( ) ;
447- expect ( Buffer . from ( value ! ) . toString ( ) ) . toBe ( 'line 1\n' ) ;
457+ expect ( stripStamps ( Buffer . from ( value ! ) . toString ( ) ) ) . toBe ( 'line 1\n' ) ;
448458 expect ( getSubscriberCount ( jobId ) ) . toBe ( 0 ) ;
449459
450460 const { done } = await reader . read ( ) ;
451461 expect ( done ) . toBe ( true ) ;
452462 } ) ;
463+
464+ it ( 'stamps every log line with a platform-style ISO timestamp, exactly once per line even when chunk boundaries fall mid-line' , async ( ) => {
465+ const jobId = 'stampedLinesJobId12' ;
466+ // Docker output is not line-aligned: one line arrives split over two appends, and one append
467+ // carries two lines. Both must come out with exactly one stamp per *line*.
468+ appendLog ( jobId , '[apify] INFO first line\n[apify] WARN second li' ) ;
469+ appendLog ( jobId , 'ne, same stamp\n' ) ;
470+ appendLog ( jobId , '[apify] INFO third line\n' ) ;
471+
472+ const log = await getFullLog ( jobId ) ;
473+ const lines = log . split ( '\n' ) . filter ( ( line ) => line . length > 0 ) ;
474+ expect ( lines ) . toHaveLength ( 3 ) ;
475+ for ( const line of lines ) expect ( line ) . toMatch ( LINE_STAMP ) ;
476+ // The continuation of the split line must NOT have been stamped mid-line.
477+ expect ( lines [ 1 ] ) . toMatch ( / s e c o n d l i n e , s a m e s t a m p $ / ) ;
478+ expect ( stripStamps ( log ) ) . toBe (
479+ '[apify] INFO first line\n[apify] WARN second line, same stamp\n[apify] INFO third line\n' ,
480+ ) ;
481+ } ) ;
482+
483+ it ( 'apify-client log redirection recovers every message from ?stream=true&raw=true (regression: Actor.call redirected nothing)' , async ( ) => {
484+ const jobId = 'redirectedLogJobId1' ;
485+ appendLog ( jobId , '[apify] INFO Initializing Actor...\n' ) ;
486+
487+ const user = await getOrCreateUserForToken ( server . token ) ;
488+ await getRegistries ( ) . runs . set ( jobId , {
489+ id : jobId ,
490+ userId : user . id ,
491+ actorId : 'x' ,
492+ buildId : 'y' ,
493+ buildNumber : '0.0.1' ,
494+ status : 'RUNNING' ,
495+ startedAt : new Date ( ) . toISOString ( ) ,
496+ defaultDatasetId : 'd' ,
497+ defaultKeyValueStoreId : 'k' ,
498+ defaultRequestQueueId : 'r' ,
499+ options : { memoryMbytes : 1024 , timeoutSecs : 300 } ,
500+ meta : { origin : 'API' } ,
501+ } ) ;
502+
503+ // The exact request apify-client's log redirection makes.
504+ const res = await fetch ( `${ server . baseUrl } /v2/actor-runs/${ jobId } /log?stream=true&raw=true` , {
505+ headers : { Authorization : `Bearer ${ server . token } ` } ,
506+ } ) ;
507+ expect ( res . status ) . toBe ( 200 ) ;
508+
509+ setTimeout ( ( ) => appendLog ( jobId , '[apify] INFO doing work\n[apify] WARN partial li' ) , 50 ) ;
510+ setTimeout ( ( ) => appendLog ( jobId , 'ne finished\n' ) , 100 ) ;
511+ setTimeout ( ( ) => markLogTerminal ( jobId ) , 150 ) ;
512+
513+ // Replicates the client's redirect parsing: buffer chunks, split on the timestamp marker, emit
514+ // only marker-delimited messages (a possibly incomplete trailing part waits in the buffer until
515+ // the final flush). Without the per-line timestamps this recovers zero messages.
516+ const splitMarker = / (?: \n | ^ ) ( \d { 4 } - \d { 2 } - \d { 2 } T \d { 2 } : \d { 2 } : \d { 2 } \. \d { 3 } Z ) / ;
517+ let streamBuffer = '' ;
518+ const messages : string [ ] = [ ] ;
519+ const flushBuffer = ( includeLastPart : boolean ) => {
520+ const allParts = streamBuffer . split ( splitMarker ) . slice ( 1 ) ;
521+ const complete = includeLastPart ? allParts : allParts . slice ( 0 , - 2 ) ;
522+ streamBuffer = includeLastPart ? '' : allParts . slice ( - 2 ) . join ( '' ) ;
523+ for ( let i = 0 ; i + 1 < complete . length ; i += 2 ) {
524+ messages . push ( `${ complete [ i ] } ${ complete [ i + 1 ] } ` . trim ( ) ) ;
525+ }
526+ } ;
527+
528+ const reader = res . body ! . getReader ( ) ;
529+ for ( ; ; ) {
530+ const { value, done } = await reader . read ( ) ;
531+ if ( done ) break ;
532+ streamBuffer += Buffer . from ( value ! ) . toString ( ) ;
533+ if ( splitMarker . test ( streamBuffer ) ) flushBuffer ( false ) ;
534+ }
535+ flushBuffer ( true ) ;
536+
537+ const contentsOnly = messages . map ( ( message ) => message . replace ( LINE_STAMP , '' ) ) ;
538+ expect ( contentsOnly ) . toEqual ( [
539+ '[apify] INFO Initializing Actor...' ,
540+ '[apify] INFO doing work' ,
541+ '[apify] WARN partial line finished' ,
542+ ] ) ;
543+ } ) ;
453544} ) ;
0 commit comments