Powershell appears to be skipping commands

I have a complex set of Powershell scripts designed to automate our student notifications upon acceptance. Here is the flow:

-- Admissions office accepts new student
-- Student Information System (SIS) database trigger writes event to web server event log
-- A task is triggered on the web server based on the event log entry
-- The task fired runs a Powershell script which extracts data from the SIS database about new incoming students, dumps it to a CSV, then fires 5 jobs (detailed later) supplying the parameter for the file path, and file name of the CSV.
-- Task 1:  Creates AD user account for student on our on-premise AD
-- Task 2:  Creates an MSOL User account for students
-- Task 3:  Creates a contact in our Admin MSOL tenant for our address book
-- Task 4:  Notifies the student of their account information <--- the task I'm having trouble with
-- Task 5:  Notifies the faculty and staff of the updated list of incoming students.

My problem is with Tasks 4 and 5, but I'm going to focus on 4. All of the above have been working fine for the last year. Suddenly, the notification to students is not failing, but skipping some of the commands. If I step through the script it works like it's supposed to. If I run it manually without stepping, it misses a bunch of steps. Below is the Powershell script. One note: to step through it, I commented out the param section and hard set the $basePath and $csvName variables myself.
param(
    [Parameter(Position=0,Mandatory=$true)][String]$csvName,
    [Parameter(Position=1,Mandatory=$true)][String]$basePath
)

if($fpath.Length -eq 0) { $fpath = "$basePath\Logs\" }
if($filedate.Length -eq 0) { $filedate = (Get-Date) }
if($log.Length -eq 0) { $log = $fpath + "NotifyStudentLog_" + $filedate.ToString("MMddyyyyHHmm") + ".log" }
if(!$csvPath) { $csvPath = "$basePath\csv\$csvName" }

(Get-Date).ToString("MM/dd/yyyy HH:mm:ss") + "LogDate,ErrorDesc,ErrorMsg,CodeModule,Location,Notes" | Out-File $log
(Get-Date).ToString("MM/dd/yyyy HH:mm:ss") + ",Informational,,NotifyStudent,,============= Begin Student Notification =============" | Out-File $log -Append
$smtpServer = "mail.myschool.edu"

Trap [System.Data.SqlClient.SqlException] {
    if($fpath.Length -eq 0) { $fpath = "$basePath\Logs\" }
    if($filedate.Length -eq 0) { $gefiledate = (Get-Date) }
    if($log.Length -eq 0) { $log = $fpath + "NotifyStudentLog_" + $filedate.ToString("MMddyyyyHHmm") + ".log" }

    $msg = $_.Exception.Message + "`n`n" + $_.Exception.ItemName + "`n`n" + $_.InvocationInfo.ScriptLineNumber + "`n`n$log"
    (Get-Date).ToString("MM/dd/yyyy HH:mm:ss") + ",Error filling DataSet," + $_.Exception.Message + ",Notify Student ,Line: " + $_.InvocationInfo.ScriptLineNumber + ",SqlError: $basePath __ $csvPath __ $log" | Out-File $log -Append
    Send-MailMessage -From errorreporting@myschool.edu -To admin@myschol.edu -Subject "Notify Student SQL Error" -Body $msg -SmtpServer $smtpServer -Port 25
}

Trap [Exception] {
    if($fpath.Length -eq 0) { $fpath = "$basePath\Logs\" }
    if($filedate.Length -eq 0) { $filedate = (Get-Date) }
    if($log.Length -eq 0) { $log = $fpath + "NotifyStudentLog_" + $filedate.ToString("MMddyyyyHHmm") + ".log" }

    $msg = $_.Exception.Message + "`n`n" + $_.Exception.ItemName + "`n`n" + $_.InvocationInfo.ScriptLineNumber + "`n`n$log"
    (Get-Date).ToString("MM/dd/yyyy HH:mm:ss") + ",General Error," + $_.Exception.Message + ",CreateMSOLUser,Line: " + $_.InvocationInfo.ScriptLineNumber + ",$basePath __ $csvPath __$log" | Out-File $log -Append    
    Send-MailMessage -From errorreporting@myschool.edu -To admin@myschol.edu -Subject "Notify Student SQL Error" -Body $msg -SmtpServer $smtpServer -Port 25
}


Import-Csv $csvPath | ForEach-Object {
    (Get-Date).ToString("MM/dd/yyyy HH:mm:ss") + ",,,CreateMSOLUser,,Processing " + $_.StudentName | Out-File $log -Append
    $greet = ""
    $NickAsFirst = ""
    if([string]::IsNullOrEmpty($_.Notified)) { $Notified = $false } else { $Notified = [System.Convert]::ToBoolean([System.Convert]::ToInt32($_.Notified)) }
    If(-not $Notified) 
    {
        if([string]::IsNullOrEmpty($_.prefix)) { $Prefix = "" } else { $Prefix = $_.prefix }
        if([string]::IsNullOrEmpty($_.StudentName)) { $FullName = "" } else { $FullName = $_.StudentName }
        if([string]::IsNullOrEmpty($_.entry_date)) { $EntryDate = "" } else { $EntryDate = $_.entry_date }
        if([string]::IsNullOrEmpty($_.nickname)) { $Nickname = "" } else { $Nickname = $_.nickname }
        if([string]::IsNullOrEmpty($_.suffix)) { $Suffix = "" } else { $Suffix = $_.suffix }
        if([string]::IsNullOrEmpty($_.ssn)) { $SSN = "4321" } else { $SSN = $_.ssn }
        if([string]::IsNullOrEmpty($_.st_addr)) { $address1 = "" } else { $address1 = $_.st_addr }
        if([string]::IsNullOrEmpty($_.add_addr)) { $address2 = "" } else { $address2 = $_.add_addr }
        if([string]::IsNullOrEmpty($_.city)) { $City = "" } else { $City = $_.city }
        if([string]::IsNullOrEmpty($_.state)) { $State = "" } else { $State = $_.state }
        if([string]::IsNullOrEmpty($_.zip)) { $ZIP = "" } else { $ZIP = $_.zip }
        if([string]::IsNullOrEmpty($_.e_mail2)) { $SecEmail = "" } else { $SecEmail = $_.e_mail2 }
        if([string]::IsNullOrEmpty($_.last_name)) { $LastName = "" } else { $LastName = $_.last_name }
        if([string]::IsNullOrEmpty($_.first_name)) { $FirstName = "" } else { $FirstName = $_.first_name }
        if([string]::IsNullOrEmpty($_.SISID)) { $SISID = "" } else { $SISID = $_.SISID }
        if([string]::IsNullOrEmpty($_.Entering)) { $Entering = "" } else { $Entering = $_.Entering }
        if([string]::IsNullOrEmpty($_.date_maint)) { $DateAccepted = "" } else { $DateAccepted = $_.date_maint }
        if([string]::IsNullOrEmpty($_.AccountsCreated)) { $Processed = "" } else { $Processed = $_.AccountsCreated }
        if([string]::IsNullOrEmpty($_.level_)) { $Acceptance = "" } elseif ( $_.level_ -eq "C") { $Acceptance = "Conditional" } else { $Acceptance = "FULL"  }
        if([string]::IsNullOrEmpty($_.pin)) { $pin = "" } else { $pin = $_.pin }
        if([string]::IsNullOrEmpty($_.DegreeSought)) {$Program = "" } else { $Program = $_.DegreeSought }
        if($Prefix.Length -gt 0) { $greet = $Prefix.Trim() + " " }
        if($Nickname.Trim().Length -gt 0) { $NickAsFirst = $NickName.Trim() } else { $NickAsFirst = $FirstName.Trim() }


        $LastFour = $SSN
        $greet += $NickAsFirst.Trim() + " " + $LastName.Trim()
        $FullName = $LastName.Trim() + ", " + $NickAsFirst.Trim()
        $email = $NickAsFirst.Trim() + "." + $LastName.Trim() + "@students.myschool.edu"
        if($pin.Length -eq 0) { $emailPass = ([password generation logic]) } else { $emailPass = $pin }

        <#
            Acceptance Letter Cross-reference

            {0} = Today's Date
            {1} = Student's full name
            {2} = Student's address
            {3} = Student's City
            {4} = Student's State
            {5} = Student's ZIP
            {6} = Student's First Name
            {7} = Semester and Year
        #>


        $msgPath = "$basePath\ExtContent\"
        $msgdate = Get-Date -Format "MM/dd/yyyy"
        [string[]]$toRecipients = "$LastName, $NickAsFirst <$SecEmail>"

        if ($Program.ToUpper() -eq "NON-DEGREE STUDIES" -or $Program.ToUpper() -eq "BIVOCATIONAL MINISTRY STUDIES") {
            $accbody = [string]::Format([Io.File]::ReadAllText($msgPath + "ndacceptance.html"),$msgdate,$FirstName + " " + $LastName,$address,$City,$State,$ZIP,$FirstName,$Entering)
        } else {
            $accbody = [string]::Format([Io.File]::ReadAllText($msgPath + "acceptance.html"),$msgdate,$FirstName + " " + $LastName,$address,$City,$State,$ZIP,$FirstName,$Entering)
        }

        if($SecEmail -ne "?") {
            $message = @{
                To = $toRecipients
                #Bcc = $bccRecipients
                From = "My SChool Admissions <admissions@myschool.edu>"
                Subject = "Welcome to My School"
                BodyAsHTML = $true
                SMTPServer = $smtpServer
                #Attachments = @($msgPath + "EmailInstructions.PDF", $msgPath + "SonisInstructions.PDF")
                Attachments = @("C:\Automation\ExtContent\EmailInstructions.PDF", "C:\Automation\ExtContent\SISInstructions.PDF")
                Body = $accbody
                ErrorAction = 'Stop'
                Port = 25
            }
            (Get-Date).ToString("MM/dd/yyyy HH:mm:ss") + ",,,,NotifyStudent,,Send message to new student [#1] ($SecEmail)" | Out-File $log -Append
            Send-MailMessage @message
            $msgSent = $true
            (Get-Date).ToString("MM/dd/yyyy HH:mm:ss") + ",,,,NotifyStudent,,Mail message sent to new student [#1] ($SecEmail)" | Out-File $log -Append
        }
        else {
            (Get-Date).ToString("MM/dd/yyyy HH:mm:ss") + ",,,,NotifyStudent,,Sutdent [$FirstName $LastName] has no personal email" | Out-File $log -Append
        }


        if($Nickname.Length -eq 0) { $addressee = $FirstName } else { $addressee = $Nickname }
        $Body = [string]::Format([Io.File]::ReadAllText($msgPath + "htmlstudentnotification.html"),$addressee,$Email,[password generation logic])

        if($SecEmail -ne "?") {
            $message = @{
                To = $toRecipients
                #Bcc = $bccRecipients
                From = "My School IT <helpdesk@myschool.edu>"
                Subject = "New My School Account Information"
                BodyAsHTML = $true
                SMTPServer = $smtpServer
                Attachments = @("C:\Automation\ExtContent\EmailInstructions.PDF", "C:\Automation\ExtContent\SISInstructions.PDF")
                Body = $Body
                ErrorAction = 'Stop'
                Port = 25
            }
            (Get-Date).ToString("MM/dd/yyyy HH:mm:ss") + ",,,,NotifyStudent,,Sending Account Login Information" | Out-File $log -Append
            Send-MailMessage @message
            $msgSent = $true
            (Get-Date).ToString("MM/dd/yyyy HH:mm:ss") + ",,,,NotifyStudent,,Account Login Information sent" | Out-File $log -Append
        }
    }

    if ($msgSent -eq $true) {
        $SQLServer = "SQLSERVER"
        $SQLDBName = "SISDB"
        $SqlConnection = New-Object System.Data.SqlClient.SqlConnection
        $SqlConnection.ConnectionString = "Server = $SQLServer; Database = $SQLDBName; User ID=xxxx; Password=xxxxxxxx;"
        $SQLQuery = "UPDATE TrackingTable SET Notified = 'True' WHERE StudentID ='$SISID'"
    
        $SqlConnection.Open()
        $SQLUpdCmd = New-Object System.Data.SqlClient.SqlCommand
        $SQLUpdCmd.CommandType = [System.Data.CommandType]::Text
        $SQLUpdCmd.CommandText = $SQLQuery
        $SQLUpdCmd.Connection = $SqlConnection
        (Get-Date).ToString("MM/dd/yyyy HH:mm:ss") + ",,,,NotifyStudent,,Executing Query" | Out-File $log -Append
        $SQLUpdCmd.ExecuteNonQuery()
        (Get-Date).ToString("MM/dd/yyyy HH:mm:ss") + ",,,,NotifyStudent,,Executing Query:::Succeeded" | Out-File $log -Append
        $msgSent = $false
    }
}

Open in new window


SQL Script for the table
USE [YOURDB]
GO

/****** Object:  Table [dbo].[appTXTrack]    Script Date: 1/5/2018 9:02:01 AM ******/
SET ANSI_NULLS ON
GO

SET QUOTED_IDENTIFIER ON
GO

SET ANSI_PADDING ON
GO

CREATE TABLE [dbo].[appTXTrack](
	[SISID] [char](9) NOT NULL,
	[mod_stat] [char](2) NOT NULL,
	[Processed] [bit] NULL CONSTRAINT [DF_appTXTrack_Processed]  DEFAULT ((0)),
	[AccountsCreated] [bit] NULL CONSTRAINT [DF_appTXTrack_AccountsCreated]  DEFAULT ((0)),
	[MSOL] [bit] NULL CONSTRAINT [DF_appTXTrack_MSOL]  DEFAULT ((0)),
	[AD] [bit] NULL CONSTRAINT [DF_appTXTrack_AD]  DEFAULT ((0)),
	[Exchange] [bit] NULL CONSTRAINT [DF_appTXTrack_Exchange]  DEFAULT ((0)),
	[Notified] [bit] NULL CONSTRAINT [DF_appTXTrack_Notified]  DEFAULT ('False'),
	[submitted] [datetime] NULL CONSTRAINT [DF_appTXTrack_submitted]  DEFAULT (getdate()),
 CONSTRAINT [PK_appTXTrack_1] PRIMARY KEY CLUSTERED 
(
	[SISID] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY]
) ON [PRIMARY]

GO

SET ANSI_PADDING OFF
GO

Open in new window


I can tell you that one of the students has a 0 (FALSE) on the "Notified" field, so the database never gets updated to set that flag to 1.

The big take-away question is this:  Why are some of my steps in the script being missed? Again, I can step through it and get the results I want, but if I let it run -- no way.
NotifyStudentLog_010520180727.log
newstudents_201701050727.csv
LVL 5
Eric GreeneDirector of TechnologyAsked:
Who is Participating?
I wear a lot of hats...

"The solutions and answers provided on Experts Exchange have been extremely helpful to me over the last few years. I wear a lot of hats - Developer, Database Administrator, Help Desk, etc., so I know a lot of things but not a lot about one thing. Experts Exchange gives me answers from people who do know a lot about one thing, in a easy to use platform." -Todd S.

Dustin SaundersDirector of OperationsCommented:
Hard to say without seeing it run off the bat, but maybe adding in more logging at various points will give you a better idea of where it's going wrong.

You can shorten your logging process up by spinning it in to a function, then if you set a debug variable you can optionally enable the extended logging as you debug and turn it off later.

$logFile = "C:\path\to\file.log"
$debug = $true

function WriteLog($message, $log)
{
	(Get-Date).ToString("MM/dd/yyyy HH:mm:ss") + $message | Out-File $log -Append
}

if ($debug) { WriteLog "string to write" $logFile }

Open in new window


You could also take some of your steps and wrap in try/catch blocks:
try { Do-Function $variable }
catch { WriteLog $_.Exception.Message $logFile }

Open in new window


To get some more detail.
0

Experts Exchange Solution brought to you by

Your issues matter to us.

Facing a tech roadblock? Get the help and guidance you need from experienced professionals who care. Ask your question anytime, anywhere, with no hassle.

Start your 7-day free trial
Eric GreeneDirector of TechnologyAuthor Commented:
I found my issue. It came down to manually running the core script and harvesting the output instead of running each one individually to find the problem. It turned out, one of my scripts had the opening curly brace on the next line instead of immediately following the foreach-object.

Edit:
For a little more detail, the core script was bailing-out on the get-job | wait-job command when running the au_NotifyStaff script. It turns out there were several jobs blocked and awaiting input due to the curly brace issue.
1
It's more than this solution.Get answers and train to solve all your tech problems - anytime, anywhere.Try it for free Edge Out The Competitionfor your dream job with proven skills and certifications.Get started today Stand Outas the employee with proven skills.Start learning today for free Move Your Career Forwardwith certification training in the latest technologies.Start your trial today
Powershell

From novice to tech pro — start learning today.

Question has a verified solution.

Are you are experiencing a similar issue? Get a personalized answer when you ask a related question.

Have a better answer? Share it in a comment.