@@ -376,30 +376,8 @@ async fn redirect(mut input: impl AsyncRead + Unpin, to: String) {
376376 }
377377}
378378
379- /// How many times a redirect target has been opened, counted for the tests
380- /// below. A reopen leaves nothing behind in the file it reopens, so counting is
381- /// the only way to see the thing that was wrong here: not what was written, but
382- /// how often the writing stopped to `fsync` and start over.
383- #[ cfg( test) ]
384- static LOG_OPENS : std:: sync:: atomic:: AtomicUsize = std:: sync:: atomic:: AtomicUsize :: new ( 0 ) ;
385-
386- /// Whether a watcher event means the log path stopped naming the file this
387- /// task holds open, so the next write has to go to a new one.
388- ///
389- /// Deliberately not `is_modify()`. On Linux `recommended_watcher` is inotify,
390- /// where `is_modify()` also matches `IN_MODIFY` -- which is exactly what the
391- /// `write_all` below generates, on its own output. Streaming 8 MiB from a
392- /// supervised child through the previous condition cost 1145 `fsync` calls and
393- /// 1146 reopens of a log nothing had rotated, one per read buffer, each one a
394- /// synchronous flush on the path a chatty child writes fastest.
395- ///
396- /// A rename is `IN_MOVED_FROM`, which inotify reports as `Modify(Name(_))` and
397- /// not as a remove, so `logrotate(8)` in its default mode still gets a reopen.
398- /// A truncate-in-place rotation -- what `dstack-vmm`'s own `logrotate` module
399- /// does, and what `logrotate(8)`'s `copytruncate` does -- needs no reopen at
400- /// all: the file is opened with `O_APPEND`, so every write goes to the current
401- /// end of it whether or not it was just emptied. That is the requirement the
402- /// vmm module's documentation states, and it is what makes this safe to drop.
379+ /// inotify reports our own `write_all` as `Modify(Data)`, so only a removal or a
380+ /// rename (logrotate's default mode) means the path no longer names our file.
403381fn is_rotation ( kind : & notify:: EventKind ) -> bool {
404382 use notify:: event:: { EventKind , ModifyKind } ;
405383 matches ! (
@@ -436,8 +414,6 @@ async fn try_redirect(input: &mut (impl AsyncRead + Unpin), to: String) -> Resul
436414 . create ( true )
437415 . append ( true )
438416 . open ( dst_path) ?;
439- #[ cfg( test) ]
440- LOG_OPENS . fetch_add ( 1 , std:: sync:: atomic:: Ordering :: SeqCst ) ;
441417
442418 loop {
443419 tokio:: select! {
@@ -473,188 +449,17 @@ async fn try_redirect(input: &mut (impl AsyncRead + Unpin), to: String) -> Resul
473449
474450#[ cfg( test) ]
475451mod log_rotation_tests {
476- use super :: * ;
477- use std:: sync:: atomic:: Ordering ;
478- use std:: time:: Duration ;
479-
480- /// [`LOG_OPENS`] is process-wide, so the tests that read it take turns.
481- static SERIAL : Mutex < ( ) > = Mutex :: new ( ( ) ) ;
482-
483- struct Redirect {
484- _serial : std:: sync:: MutexGuard < ' static , ( ) > ,
485- opens_at_start : usize ,
486- }
487-
488- impl Redirect {
489- fn start ( ) -> Self {
490- let serial = SERIAL . lock ( ) . unwrap_or_else ( |err| err. into_inner ( ) ) ;
491- Self {
492- opens_at_start : LOG_OPENS . load ( Ordering :: SeqCst ) ,
493- _serial : serial,
494- }
495- }
496-
497- fn opens ( & self ) -> usize {
498- LOG_OPENS . load ( Ordering :: SeqCst ) - self . opens_at_start
499- }
500- }
501-
502- /// Wait for `condition`, or give the assertion after it something to say.
503- async fn settle ( condition : impl Fn ( ) -> bool ) {
504- for _ in 0 ..400 {
505- if condition ( ) {
506- return ;
507- }
508- tokio:: time:: sleep ( Duration :: from_millis ( 10 ) ) . await ;
509- }
510- }
511-
512- fn size ( path : & Path ) -> u64 {
513- fs:: metadata ( path) . map ( |meta| meta. len ( ) ) . unwrap_or ( 0 )
514- }
515-
516- /// A child's own output must not look like a rotation.
517- ///
518- /// inotify reports every `write_all` below as `IN_MODIFY` on the log path,
519- /// which the watcher used to accept, so each read buffer cost an `fsync`
520- /// and a reopen. Measured on the real binary before this changed: 8 MiB of
521- /// child output produced 1145 `fsync` calls and 1146 opens of a log nothing
522- /// had rotated.
523- #[ tokio:: test]
524- async fn streaming_output_does_not_reopen_the_log ( ) {
525- let counter = Redirect :: start ( ) ;
526- let dir = tempfile:: tempdir ( ) . unwrap ( ) ;
527- let log = dir. path ( ) . join ( "stdout.log" ) ;
528-
529- let ( mut writer, mut reader) = tokio:: io:: duplex ( 64 * 1024 ) ;
530- let path = log. to_string_lossy ( ) . into_owned ( ) ;
531- let redirect = tokio:: spawn ( async move { try_redirect ( & mut reader, path) . await } ) ;
532-
533- let chunk = vec ! [ b'x' ; 8192 ] ;
534- for _ in 0 ..128 {
535- tokio:: io:: AsyncWriteExt :: write_all ( & mut writer, & chunk)
536- . await
537- . unwrap ( ) ;
538- }
539- drop ( writer) ;
540- redirect. await . unwrap ( ) . unwrap ( ) ;
541-
542- assert_eq ! ( size( & log) , 128 * 8192 ) ;
543- assert_eq ! (
544- counter. opens( ) ,
545- 1 ,
546- "1 MiB of output reopened the log {} times" ,
547- counter. opens( )
548- ) ;
549- }
550-
551- /// A rotation that renames the log away still has to be followed.
552- ///
553- /// inotify reports the rename as `IN_MOVED_FROM`, which `notify` maps to
554- /// `Modify(Name(_))` rather than to a remove -- so dropping `is_modify()`
555- /// wholesale would have left `logrotate(8)`'s default mode writing into an
556- /// unlinked inode forever.
557- #[ tokio:: test]
558- async fn a_renamed_log_is_reopened ( ) {
559- let counter = Redirect :: start ( ) ;
560- let dir = tempfile:: tempdir ( ) . unwrap ( ) ;
561- let log = dir. path ( ) . join ( "stdout.log" ) ;
562- let rotated = dir. path ( ) . join ( "stdout.log.1" ) ;
563-
564- let ( mut writer, mut reader) = tokio:: io:: duplex ( 64 * 1024 ) ;
565- let path = log. to_string_lossy ( ) . into_owned ( ) ;
566- let redirect = tokio:: spawn ( async move { try_redirect ( & mut reader, path) . await } ) ;
567-
568- tokio:: io:: AsyncWriteExt :: write_all ( & mut writer, b"before\n " )
569- . await
570- . unwrap ( ) ;
571- settle ( || size ( & log) == 7 ) . await ;
572-
573- fs:: rename ( & log, & rotated) . unwrap ( ) ;
574- settle ( || log. exists ( ) ) . await ;
575- assert ! ( log. exists( ) , "the log was never reopened after the rename" ) ;
576-
577- tokio:: io:: AsyncWriteExt :: write_all ( & mut writer, b"after\n " )
578- . await
579- . unwrap ( ) ;
580- drop ( writer) ;
581- redirect. await . unwrap ( ) . unwrap ( ) ;
582-
583- assert_eq ! ( fs:: read_to_string( & rotated) . unwrap( ) , "before\n " ) ;
584- assert_eq ! ( fs:: read_to_string( & log) . unwrap( ) , "after\n " ) ;
585- // One rename reaches the watcher twice: `notify` reports `IN_MOVED_FROM`
586- // as `Modify(Name(From))` and then synthesizes a `Modify(Name(Both))`
587- // carrying the old path as well. Both name this log, so a rotation
588- // costs a reopen more than it strictly needs. Bounded by how often a
589- // log is rotated, which is the point.
590- assert ! (
591- counter. opens( ) >= 2 ,
592- "the rename was never followed: {} opens" ,
593- counter. opens( )
594- ) ;
595- }
596-
597- /// The rotation dstack actually performs needs no reopen.
598- ///
599- /// `dstack-vmm`'s `logrotate` module copies the log and then truncates it
600- /// in place, precisely so a live writer's fd stays valid; `logrotate(8)`'s
601- /// `copytruncate` does the same. The file is opened with `O_APPEND`, so the
602- /// next write lands at the new end of it. Nothing to follow, and the
603- /// truncation is an `IN_MODIFY` this must not react to -- reacting is what
604- /// made a chatty child cost an `fsync` per buffer.
605- #[ tokio:: test]
606- async fn a_truncated_log_keeps_appending_without_a_reopen ( ) {
607- let counter = Redirect :: start ( ) ;
608- let dir = tempfile:: tempdir ( ) . unwrap ( ) ;
609- let log = dir. path ( ) . join ( "stdout.log" ) ;
610-
611- let ( mut writer, mut reader) = tokio:: io:: duplex ( 64 * 1024 ) ;
612- let path = log. to_string_lossy ( ) . into_owned ( ) ;
613- let redirect = tokio:: spawn ( async move { try_redirect ( & mut reader, path) . await } ) ;
614-
615- tokio:: io:: AsyncWriteExt :: write_all ( & mut writer, b"before\n " )
616- . await
617- . unwrap ( ) ;
618- settle ( || size ( & log) == 7 ) . await ;
619-
620- fs:: write ( & log, b"" ) . unwrap ( ) ;
621- tokio:: io:: AsyncWriteExt :: write_all ( & mut writer, b"after\n " )
622- . await
623- . unwrap ( ) ;
624- drop ( writer) ;
625- redirect. await . unwrap ( ) . unwrap ( ) ;
626-
627- // No sparse hole: `O_APPEND` put the write at the current end of file,
628- // not at the offset the writer had reached before the truncation.
629- assert_eq ! ( fs:: read_to_string( & log) . unwrap( ) , "after\n " ) ;
630- assert_eq ! ( counter. opens( ) , 1 , "a truncation is not a rotation" ) ;
631- }
452+ use super :: is_rotation;
453+ use notify:: event:: { DataChange , EventKind , ModifyKind , RemoveKind , RenameMode } ;
632454
633455 #[ test]
634- fn only_a_removal_or_a_rename_counts_as_a_rotation ( ) {
635- use notify:: event:: {
636- AccessKind , CreateKind , DataChange , EventKind , MetadataKind , ModifyKind , RemoveKind ,
637- RenameMode ,
638- } ;
639-
640- for kind in [
641- EventKind :: Remove ( RemoveKind :: File ) ,
642- EventKind :: Remove ( RemoveKind :: Any ) ,
643- EventKind :: Modify ( ModifyKind :: Name ( RenameMode :: From ) ) ,
644- EventKind :: Modify ( ModifyKind :: Name ( RenameMode :: Any ) ) ,
645- ] {
646- assert ! ( is_rotation( & kind) , "{kind:?} is a rotation" ) ;
647- }
648- for kind in [
649- // What every `write_all` in `try_redirect` produces.
650- EventKind :: Modify ( ModifyKind :: Data ( DataChange :: Any ) ) ,
651- EventKind :: Modify ( ModifyKind :: Data ( DataChange :: Content ) ) ,
652- EventKind :: Modify ( ModifyKind :: Metadata ( MetadataKind :: Any ) ) ,
653- EventKind :: Modify ( ModifyKind :: Any ) ,
654- EventKind :: Create ( CreateKind :: File ) ,
655- EventKind :: Access ( AccessKind :: Any ) ,
656- ] {
657- assert ! ( !is_rotation( & kind) , "{kind:?} is not a rotation" ) ;
658- }
456+ fn only_a_removal_or_a_rename_is_a_rotation ( ) {
457+ assert ! ( is_rotation( & EventKind :: Remove ( RemoveKind :: File ) ) ) ;
458+ assert ! ( is_rotation( & EventKind :: Modify ( ModifyKind :: Name (
459+ RenameMode :: From
460+ ) ) ) ) ;
461+ assert ! ( !is_rotation( & EventKind :: Modify ( ModifyKind :: Data (
462+ DataChange :: Any
463+ ) ) ) ) ;
659464 }
660465}
0 commit comments