1.4. Migrating from SAS to R: A Skill Conversion Guide

1.4.10. Log Messages: SAS Log vs R Console

This guide compares SAS log and R console approaches for handling diagnostic messages, warnings, and errors, highlighting key similarities and differences between the two languages.

1. Basic Log Messaging

SAS Example

/* SAS informational message */
data _null_;
  put "Processing data step at " datetime.;
run;

/* SAS warning via %PUT */
%put WARNING: Missing observations detected;

/* SAS error via %PUT */
%put ERROR: Data does not meet validation criteria;

/* SAS error from data step */
data invalid;
  set sashelp.class;
  if age < 0 then abort;
run;

Explanation (SAS):

• The SAS log automatically collects all output messages
• PUT statement writes text to the log from DATA steps
• %PUT writes messages from macro code
• WARNING: and ERROR: prefixes create highlighted warning/error messages
• abort statement halts execution of the current DATA step
• SAS continues processing subsequent code even after most errors
• Messages appear in the log window or log file in batch mode

R Example

# R informational message
message("Processing data at ", format(Sys.time(), "%Y-%m-%d %H:%M:%S"))

# R warning message
if (any(is.na(data$age))) {
  warning("Missing values detected in age variable")
}

# R error message
if (nrow(data) == 0) {
  stop("Dataset contains no observations")
}

# R error with condition
validate_age <- function(age) {
  if (any(age < 0, na.rm = TRUE)) {
    stop("Negative age values detected")
  }
}

Explanation (R):

• R writes messages directly to the console (no separate log)
• message() creates informational messages
• warning() creates warning messages (code continues)
• stop() creates error messages that halt execution
• try() and tryCatch() can catch errors for graceful handling
• suppressMessages(), suppressWarnings() can hide output
• Messages can be redirected using sink() or logging packages

Example Output in SAS Log:

NOTE: DATA statement used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds
      
Processing data step at 01JAN2023:14:30:45.000

WARNING: Missing observations detected

ERROR: Data does not meet validation criteria

ERROR: The data set WORK.INVALID may be incomplete. When this step was stopped there were 0 observations and 5 variables.

Example Output in R Console:

Processing data at 2023-01-01 14:30:45

Warning: Missing values detected in age variable

Error: Dataset contains no observations

2. Log Message Types and Features

SAS Example

/* Create sample data for age check */
data patients;
  input PatID $ Age Treatment $;
datalines;
P001 45 A
P002 -2 B
P003 . A
P004 62 B
;
run;

/* Validation with custom messages */
data validated;
  set patients;
  
  /* Count issues for final report */
  if _N_ = 1 then do;
    call symputx('negative_count', 0);
    call symputx('missing_count', 0);
  end;
  
  /* Check age values */
  if Age < 0 then do;
    put "WARNING: Patient " PatID " has invalid negative age " Age;
    call symputx('negative_count', symget('negative_count') + 1);
  end;
  
  if Age = . then do;
    put "NOTE: Patient " PatID " has missing age";
    call symputx('missing_count', symget('missing_count') + 1);
  end;
run;

/* Final validation summary */
%put NOTE: Data validation complete;
%put %sysfunc(ifc(&negative_count > 0, 
    %str(WARNING: &negative_count patients with negative ages),
    %str(NOTE: No patients with negative ages)));
%put %sysfunc(ifc(&missing_count > 0, 
    %str(NOTE: &missing_count patients with missing ages),
    %str(NOTE: No patients with missing ages)));

Explanation (SAS):

• PUT statements generate custom log messages during data step execution
• Messages can include variable values like PatID and Age
• call symputx() creates macro variables to track counts across observations
• %PUT with conditional logic generates summary messages
• Different message types (NOTE/WARNING) help highlight issues by severity
• Messages appear chronologically as the code executes

R Example

# Show input data
patients <- data.frame(
  PatID = c("P001", "P002", "P003", "P004"),
  Age = c(45, -2, NA, 62),
  Treatment = c("A", "B", "A", "B")
)
print(patients)

# No package needed for base functions
# Function to validate age values
validate_age_data <- function(data) {
  # Initialize counters
  negative_count <- 0
  missing_count <- 0
  
  # Check each observation
  for (i in 1:nrow(data)) {
    # Check negative age
    if (!is.na(data$Age[i]) && data$Age[i] < 0) {
      warning(sprintf("Patient %s has invalid negative age %d", 
                     data$PatID[i], data$Age[i]))
      negative_count <- negative_count + 1
    }
    
    # Check missing age
    if (is.na(data$Age[i])) {
      message(sprintf("Patient %s has missing age", data$PatID[i]))
      missing_count <- missing_count + 1
    }
  }
  
  # Final validation summary
  message("Data validation complete")
  
  if (negative_count > 0) {
    warning(sprintf("%d patients with negative ages", negative_count))
  } else {
    message("No patients with negative ages")
  }
  
  if (missing_count > 0) {
    message(sprintf("%d patients with missing ages", missing_count))
  } else {
    message("No patients with missing ages")
  }
  
  return(data)
}

# Run validation
validated <- validate_age_data(patients)

Explanation (R):

• R combines validation logic and messaging in a function
• sprintf() formats strings with variable values
• message() creates informational notes (similar to SAS NOTEs)
• warning() creates warning messages for potential issues
• Messages can be generated conditionally inside loops
• R returns results at the end with a summary report

Input Data:

Expected SAS Log Output:

WARNING: Patient P002 has invalid negative age -2
NOTE: Patient P003 has missing age

NOTE: Data validation complete
WARNING: 1 patients with negative ages
NOTE: 1 patients with missing ages

Expected R Console Output:

Patient P003 has missing age
Data validation complete
1 patients with missing ages
Warning messages:
1: In validate_age_data(patients) :
  Patient P002 has invalid negative age -2
2: In validate_age_data(patients) : 1 patients with negative ages

3. Error Handling Approaches

SAS Example

/* Basic error handling with %SYSERR */
%macro import_check(file=);
  /* Try to import the file */
  proc import datafile="&file"
      out=work.imported
      dbms=xlsx replace;
  run;
  
  /* Check if import succeeded */
  %if &syserr > 0 %then %do;
    %put ERROR: Import failed with error code &syserr;
    %put ERROR: &syserrortext;
    %put ERROR: Skipping subsequent processing;
    %return;
  %end;
  
  %put NOTE: Import successful, proceeding with analysis;
  proc means data=work.imported;
  run;
%mend;

/* Test with nonexistent file */
%import_check(file=nonexistent.xlsx);

Explanation (SAS):

• &SYSERR automatic macro variable contains the error status code
• &SYSERRORTEXT contains textual description of the error
• %IF-%THEN logic allows conditional execution based on error status
• %RETURN exits the macro when an error is detected
• SAS will execute the entire macro unless it's explicitly terminated
• Error details are recorded in the SAS log

R Example

# Explicitly load readxl for Excel import
library(readxl)

# Basic error handling with tryCatch
import_check <- function(file) {
  # Try to import the file
  result <- tryCatch(
    {
      # Attempt the import
      imported <- readxl::read_excel(file)
      message("Import successful, proceeding with analysis")
      
      # Perform additional analysis
      summary_stats <- summary(imported)
      return(list(data = imported, summary = summary_stats, status = "success"))
    },
    error = function(e) {
      # Handle the error
      message("ERROR: Import failed")
      message(paste("ERROR:", e$message))
      message("ERROR: Skipping subsequent processing")
      return(list(data = NULL, summary = NULL, status = "failed", 
                 error = e$message))
    },
    warning = function(w) {
      # Handle warnings
      message("WARNING: Import completed with warnings")
      message(paste("WARNING:", w$message))
      # Still try to proceed
      imported <- readxl::read_excel(file)
      summary_stats <- summary(imported)
      return(list(data = imported, summary = summary_stats, 
                 status = "warning", warning = w$message))
    }
  )
  
  return(result)
}

# Test with nonexistent file
result <- import_check("nonexistent.xlsx")
if (result$status != "success") {
  message("Processing halted due to import issues")
} else {
  message("Continue with further processing...")
}

Explanation (R):

• tryCatch() wraps code that might produce errors or warnings
• Separate handler functions for error and warning conditions
• Error handler prevents the program from stopping and captures details
• Return value includes error status and information
• Calling code checks the status to determine next steps
• Structured error handling similar to try-catch in other languages

Expected SAS Log Output:

ERROR: Import failed with error code 4
ERROR: File NONEXISTENT.XLSX does not exist.
ERROR: Skipping subsequent processing

Expected R Console Output:

> # Test with nonexistent file
> result <- import_check("nonexistent.xlsx")
ERROR: Import failed
ERROR: `path` does not exist: ‘nonexistent.xlsx’
ERROR: Skipping subsequent processing
> if (result$status != "success") {
+   message("Processing halted due to import issues")
+ } else {
+   message("Continue with further processing...")
+ }
Processing halted due to import issues

4. Advanced Logging Techniques

SAS Example

/* Create a custom logging macro */
%macro log(level, message);
  %let timestamp = %sysfunc(datetime(), datetime20.);
  %let level = %upcase(&level);
  
  /* Standardized format for all log messages */
  %put &level [&timestamp]: &message;
  
  /* Write to external log file as well */
  %if %sysfunc(fileexist(mylog.txt)) %then %do;
    filename logfile "mylog.txt" mod;
  %end;
  %else %do;
    filename logfile "mylog.txt";
  %end;
  
  data _null_;
    file logfile;
    put "&level [&timestamp]: &message";
  run;
  
  filename logfile clear;
%mend;

/* Using the custom log macro */
%log(INFO, Starting data processing);

data processed;
  set sashelp.class;
  if age < 12 then do;
    %log(WARNING, Found subjects under 12);
  end;
  
  if age > 16 then delete;
run;

%log(INFO, Processing complete);

Explanation (SAS):

• Custom %log macro provides standardized logging format
• Timestamp added to each message for tracking
• Messages written to both SAS log and external file
• Consistent format makes logs easier to parse and analyze
• Log levels (INFO, WARNING) help categorize messages
• External log file persists after the SAS session ends

R Example

# No package needed for base logging
# Show input data
data <- data.frame(age = c(10, 15, 17, 8, 20))
print(data)

# Create a basic custom logging system
create_logger <- function(log_file = NULL) {
  # Initialize log file if provided
  if (!is.null(log_file)) {
    # Create or truncate the log file
    cat("", file = log_file)
  }
  
  # Return logger functions
  list(
    info = function(msg) {
      timestamp <- format(Sys.time(), "%Y-%m-%d %H:%M:%S")
      formatted <- sprintf("INFO [%s]: %s", timestamp, msg)
      message(formatted)
      if (!is.null(log_file)) {
        cat(formatted, "\n", file = log_file, append = TRUE)
      }
    },
    warning = function(msg) {
      timestamp <- format(Sys.time(), "%Y-%m-%d %H:%M:%S")
      formatted <- sprintf("WARNING [%s]: %s", timestamp, msg)
      warning(formatted)
      if (!is.null(log_file)) {
        cat(formatted, "\n", file = log_file, append = TRUE)
      }
    },
    error = function(msg) {
      timestamp <- format(Sys.time(), "%Y-%m-%d %H:%M:%S")
      formatted <- sprintf("ERROR [%s]: %s", timestamp, msg)
      if (!is.null(log_file)) {
        cat(formatted, "\n", file = log_file, append = TRUE)
      }
      stop(formatted, call. = FALSE)
    }
  )
}

# Create and use a logger
log <- create_logger("mylog.txt")

log$info("Starting data processing")

# Process data with logging
process_data <- function(data, log) {
  log$info(paste("Processing", nrow(data), "records"))
  
  young_subjects <- sum(data$age < 12)
  if (young_subjects > 0) {
    log$warning(paste("Found", young_subjects, "subjects under 12"))
  }
  
  processed <- data[data$age <= 16, ]
  
  log$info(paste("Retained", nrow(processed), "records after filtering"))
  return(processed)
}

# Run with logging
processed <- process_data(data, log)

log$info("Processing complete")

Explanation (R):

• Creates a custom logging system using a closure
• Logger provides consistent formatting with timestamps
• Different logging levels (info, warning, error)
• Writes to both console and external log file
• Returns functions that are used throughout the code
• Similar to professional logging packages but simplified

Expected Output in mylog.txt:

> processed <- process_data(data, log)
INFO [2025-07-26 04:49:07]: Processing 5 records
INFO [2025-07-26 04:49:07]: Retained  records after filtering
Warning message:
In log$warning(paste("Found", young_subjects, "subjects under 12")) :
  WARNING [2025-07-26 04:49:07]: Found 2 subjects under 12
> 
> log$info("Processing complete")
INFO [2025-07-26 04:49:07]: Processing complete

5. Beyond Basics: Structured Logging with Packages

SAS Macro-based Logging Framework Example

/* SAS Advanced Logging Framework */
%macro init_logger(log_level=INFO, log_file=);
  %global log_level log_file log_level_num;
  
  %let log_level = %upcase(&log_level);
  %let log_file = &log_file;
  
  /* Set numeric log level for threshold comparison */
  %if &log_level = DEBUG %then %let log_level_num = 1;
  %else %if &log_level = INFO %then %let log_level_num = 2;
  %else %if &log_level = WARNING %then %let log_level_num = 3;
  %else %if &log_level = ERROR %then %let log_level_num = 4;
  %else %if &log_level = FATAL %then %let log_level_num = 5;
  %else %let log_level_num = 2; /* Default to INFO */
  
  /* Initialize log file if provided */
  %if %length(&log_file) > 0 %then %do;
    data _null_;
      file "&log_file";
      put "# Log initialized at %sysfunc(datetime(), datetime20.) with level &log_level";
    run;
  %end;
  
  %put NOTE: Logger initialized with level &log_level;
%mend;

/* Logger function with threshold level */
%macro log(level, message);
  %local level_num timestamp;
  %let level = %upcase(&level);
  
  /* Set level number for comparison */
  %if &level = DEBUG %then %let level_num = 1;
  %else %if &level = INFO %then %let level_num = 2;
  %else %if &level = WARNING %then %let level_num = 3;
  %else %if &level = ERROR %then %let level_num = 4;
  %else %if &level = FATAL %then %let level_num = 5;
  %else %let level_num = 2; /* Default to INFO */
  
  /* Only log if at or above threshold */
  %if &level_num >= &log_level_num %then %do;
    %let timestamp = %sysfunc(datetime(), datetime20.);
    
    /* Log to SAS log */
    %if &level = WARNING %then %put WARNING [&timestamp]: &message;
    %else %if &level = ERROR %then %put ERROR [&timestamp]: &message;
    %else %if &level = FATAL %then %put ERROR [&timestamp]: (FATAL) &message;
    %else %put NOTE: &level [&timestamp]: &message;
    
    /* Log to file if provided */
    %if %length(&log_file) > 0 %then %do;
      data _null_;
        file "&log_file" mod;
        put "&level [&timestamp]: &message";
      run;
    %end;
  %end;
%mend;

Explanation (SAS Advanced Logging):

• Creates a robust logging framework with threshold levels
• Only logs messages at or above the configured threshold
• Consistent formatting across all message types
• Configurable output to SAS log and/or external file
• Log levels follow industry standards (DEBUG, INFO, WARNING, etc.)
• Macro variables provide global configuration

R Package-based Logging Example

# Install the 'logger' package if not already installed
# install.packages("logger")

library(logger)

# Configure logger threshold (INFO and above)
log_threshold(INFO)

# Use a simple layout without caller info
log_layout(layout_glue_generator(
  format = "{level} [{time}] {msg}"
))

# Log to both console and file
log_appender(appender_tee("application.log"))

# Basic log messages
log_info("Starting data import process")

# Function to import data safely
import_data <- function(file_path) {
  log_info("Attempting to import file: {file_path}")
  
  if (!file.exists(file_path)) {
    log_error("File not found: {file_path}")
    return(NULL)
  }
  
  tryCatch({
    data <- read.csv(file_path)
    log_info("Successfully imported {nrow(data)} rows from {file_path}")
    return(data)
  }, error = function(e) {
    log_error("Import failed: {conditionMessage(e)}")
    return(NULL)
  }, warning = function(w) {
    log_warn("Import warning: {conditionMessage(w)}")
    # Try importing anyway
    data <- read.csv(file_path)
    return(data)
  })
}

# Simulate a module execution
log_info("Starting module: data_processing")
result <- import_data("mydata.csv")

if (is.null(result)) {
  log_error("Processing failed due to import errors")
} else {
  log_info("Processing completed successfully")
}

Explanation (R Advanced Logging):

• Uses the logger package for professional logging capabilities
• Configures log threshold level, layout, and multiple appenders
• Includes structured contextual information with messages
• Consistent formatting across all code
• Log layout is highly customizable
• Multiple appenders allow output to console, files, databases, etc.
• Can be configured in a central location and used throughout the application

Expected Output in application.log:

> # Simulate a module execution
> log_info("Starting module: data_processing")
INFO [2025-07-26 04:55:29.635103] Starting module: data_processing
> result <- import_data("mydata.csv")
INFO [2025-07-26 04:55:29.637604] Attempting to import file: mydata.csv
ERROR [2025-07-26 04:55:29.640514] File not found: mydata.csv
> 
> if (is.null(result)) {
+   log_error("Processing failed due to import errors")
+ } else {
+   log_info("Processing completed successfully")
+ }
ERROR [2025-07-26 04:55:29.645951] Processing failed due to import errors

6. Profiling and Debugging

SAS Example

/* Enable detailed timing */
options fullstimer;

/* Enable macro debugging */
options mlogic mprint symbolgen;

/* Performance tracking */
%macro perf_log(step);
  %put NOTE: Starting step "&step" at %sysfunc(datetime(), datetime.);
  %global _timer_&step;
  %let _timer_&step = %sysfunc(datetime());
%mend;

%macro perf_end(step);
  %local end_time duration;
  %let end_time = %sysfunc(datetime());
  %let duration = %sysevalf(&end_time - &&_timer_&step);
  %put NOTE: Completed step "&step" in &duration seconds;
%mend;

/* Use performance tracking */
%perf_log(data_import);
data work.imported;
  set sashelp.class;
run;
%perf_end(data_import);

%perf_log(data_processing);
proc sort data=work.imported;
  by age;
run;
%perf_end(data_processing);

/* Reset options */
options nomlogic nomprint nosymbolgen;

Explanation (SAS Performance Tracking):

• fullstimer option provides detailed execution time information
• Macro debugging options help trace execution flow
• Custom macros track timing for specific code sections
• SAS log includes automatic performance statistics
• Provides visibility into resource usage and bottlenecks

R Example

# Basic timing with system.time
system.time({
  # Code to time
  Sys.sleep(1)
})

# More flexible timing with tictoc
library(tictoc)
library(pryr)

# Performance tracking function
perf_track <- function(description, expr) {
  message(paste("Starting", description, "at", format(Sys.time())))
  tic(description)
  result <- eval(expr)
  toc(log = TRUE)
  return(result)
}

# Memory usage before operation
mem_start <- mem_used()
message(paste("Memory before:", format(mem_start, units = "auto")))

# Track performance of data operations
imported <- perf_track("data_import", {
  # Simulating data import
  Sys.sleep(1) 
  data <- datasets::iris
  data
})

processed <- perf_track("data_processing", {
  # Simulating data processing
  Sys.sleep(0.5)
  processed <- imported[order(imported$Sepal.Length), ]
  processed
})

# Memory usage after operations
mem_end <- mem_used()
message(paste("Memory after:", format(mem_end, units = "auto")))
message(paste("Memory change:", format(mem_end - mem_start, units = "auto")))

# Get timing log
timing_log <- tic.log(format = TRUE)
print(timing_log)

# Reset timer log
tic.clearlog()

# Advanced profiling with profvis
library(profvis)
profvis({
  # Code to profile
  data <- datasets::iris
  result <- lapply(1:10, function(i) {
    Sys.sleep(0.1)
    mean(data$Sepal.Length)
  })
})

Explanation (R Performance Tracking):

• system.time() provides basic execution timing
• tictoc package offers flexible timing with nested operations
• mem_used() tracks memory consumption
• Custom functions combine timing and messaging
• profvis provides interactive visualization of performance
• Helps identify bottlenecks and resource-intensive operations
• RStudio integration for debugging and profiling

Expected R Console Output:

Starting data_import at 2025-01-01 17:30:45
data_import: 1.01 sec elapsed
Starting data_processing at 2025-01-01 17:30:46
data_processing: 0.51 sec elapsed
Memory before: 50.5 MB
Memory after: 51.2 MB
Memory change: 700 KB
[1] "data_import: 1.01 sec elapsed"
[2] "data_processing: 0.51 sec elapsed"

7. Best Practices for Logging

• Be Consistent

  • Use standard log levels (DEBUG, INFO, WARNING, ERROR)
  • Format messages consistently for easier reading and parsing
  • Include timestamps for troubleshooting timing issues

• Log Appropriate Information

  • Include context data like record counts and parameters
  • Avoid logging sensitive information (PII, passwords)
  • Balance verbosity against performance impacts

• Handle Errors Gracefully

  • Log error details for easier troubleshooting
  • Include error locations (file, line number, function)
  • Consider user-friendly error messages vs. technical details

• Configure Log Levels

  • Use DEBUG during development
  • Use INFO or WARNING in production
  • Allow runtime configuration when possible

• Log Management

  • Implement log rotation for long-running applications
  • Consider log file size limits
  • Archive logs for compliance where needed

• Structured Logging

  • Use structured formats (e.g., JSON) for machine-readable logs
  • Include contextual information (user, session, process)
  • Enable easy filtering and search

• Performance Considerations

  • Use conditional logging for high-volume messages
  • Buffer log messages when appropriate
  • Consider asynchronous logging for performance-critical code

**Resource download links**

1.4.9.-Log-Messages-SAS-Log-vs-R-Console.zip