1

I have a PowerShell script which invokes POST REST API calls to Microsoft Graph. At the start of the script, I use the Start-Transcript -Append "$($MyInvocation.MyCommand.Name).log" cmdlet and at the end of the script, I use the Stop-Transcript cmdlet, so everything output to the console is (well, should be) logged to a file.

Everything is logged to the file until the part of my script that uses the Invoke-RestMethod cmdlet is reached and outputs a response.

Here is the console output:

Transcript started, output file is DisableInactivePendingInviteAccounts.ps1.log
[20/12/2021 12:27:26] Getting API token...
[20/12/2021 12:27:26] Got API token!
[20/12/2021 12:27:26] Getting all user data...
[20/12/2021 12:27:37] Got all user data!
[20/12/2021 12:27:37] Determining which user accounts to disable...
[20/12/2021 12:27:37] User accounts to disable determined!
[20/12/2021 12:27:37] Building JSON batch request(s)...
[20/12/2021 12:27:37] Built JSON batch request #1, size: 4
[20/12/2021 12:27:37] Built JSON batch request(s)!
[20/12/2021 12:27:37] Making API request(s)...

responses
---------
{@{id=2; status=204; headers=; body=}, @{id=3; status=204; headers=; body=}, @{id=1; status=204; headers=; body=}, @...
[20/12/2021 12:27:38] API requests made!
[20/12/2021 12:27:38] User accounts disabled (4)
Transcript stopped, output file is <path>\DisableInactivePendingInviteAccounts.ps1.log

Here is the log file contents:

**********************
Transcript started, output file is DisableInactivePendingInviteAccounts.ps1.log
[20/12/2021 12:27:26] Getting API token...
[20/12/2021 12:27:26] Got API token!
[20/12/2021 12:27:26] Getting all user data...
[20/12/2021 12:27:37] Got all user data!
[20/12/2021 12:27:37] Determining which user accounts to disable...
[20/12/2021 12:27:37] User accounts to disable determined!
[20/12/2021 12:27:37] Building JSON batch request(s)...
[20/12/2021 12:27:37] Built JSON batch request #1, size: 4
[20/12/2021 12:27:37] Built JSON batch request(s)!
[20/12/2021 12:27:37] Making API request(s)...

**********************
Windows PowerShell transcript end
End time: 20211220122738
**********************

As you can see, the log file contains nothing past the "Making API request(s)..." output, despite the console doing so. Why is this?

EDIT:

Full code:

# Starts transcript so that outputs are logged to a file
Start-Transcript -Append "$($MyInvocation.MyCommand.Name).log"

# Causes the script to stop if an error occurs
$ErrorActionPreference = "Stop"

#######################################
# Connects to Graph and authenticates #
#######################################

Write-Output "[$(Get-Date -Format 'dd/MM/yyyy HH:mm:ss')] Getting API token..."

$openid = Invoke-RestMethod -Uri <uri>
$bodyTokenRequest = @{
    client_id = <id>
    client_secret = <secret>
    redirect_uri = "https://localhost"
    grant_type = "client_credentials"
    resource = "https://graph.microsoft.com"
}
$request = Invoke-RestMethod -Method Post -Uri $openid.token_endpoint -Body $bodyTokenRequest

Write-Output "[$(Get-Date -Format 'dd/MM/yyyy HH:mm:ss')] Got API token!"

#######################################
#   Retrieves all users from Graph    #
#######################################

# The initial URI to use
$uri = 'https://graph.microsoft.com/beta/users?$select=signInActivity'

# Empty array to be populated with users
$users = @()

# Populates $users with entries from every page from Graph
Write-Output "[$(Get-Date -Format 'dd/MM/yyyy HH:mm:ss')] Getting all user data..."

do
{
    # API call to retrieve page of users and URI to next page
    $api = Invoke-RestMethod -Method Get -Headers @{Authorization = "Bearer $($request.access_token)"} -Uri $uri
    
    # Adds users from the page to $users
    $users += $api.value
    
    # New URI for next page
    $uri = $api."@odata.nextLink"
}
until ([string]::IsNullOrWhiteSpace($uri))

Write-Output "[$(Get-Date -Format 'dd/MM/yyyy HH:mm:ss')] Got all user data!"

#######################################
#      Does stuff with the data       #
#######################################

# Gets all guest users who have not signed in within a year ago from now or since their account creation
Write-Output "[$(Get-Date -Format 'dd/MM/yyyy HH:mm:ss')] Determining which user accounts to disable..."

$usersToDisable = @()
$aYearAgo = (Get-Date).AddYears(-1)
foreach ($user in $users)
{
    # The current user's last sign-in date
    $lastSignInDateTime = $user.signInActivity.lastSignInDateTime
    
    # Whether or not the current user has ever signed in before
    $hasSignedInBefore = ![string]::IsNullOrWhiteSpace($lastSignInDateTime)
    
    if ($user.accountEnabled -and $user.userType -eq "Guest" -and (($hasSignedInBefore -and [DateTime]$lastSignInDateTime -lt $aYearAgo) -or (!$hasSignedInBefore -and [DateTime]$user.createdDateTime -lt $aYearAgo)))
    {
        $usersToDisable += $user
    }
}

if ($usersToDisable.Count -gt 0)
{
    Write-Output "[$(Get-Date -Format 'dd/MM/yyyy HH:mm:ss')] User accounts to disable determined!"
    
    # Creates and populates $batchRequests with JSON batch requests, each containing 20 requests (or less) due to Graph limitations
    Write-Output "[$(Get-Date -Format 'dd/MM/yyyy HH:mm:ss')] Building JSON batch request(s)..."
    
    $batchRequests = @()
    $batchRequest = @{}
    $requestsList = New-Object System.Collections.ArrayList
    for ($i = 0; $i -lt $usersToDisable.Count; $i++)
    {
        # Adds request to the current JSON batch request
        $requestsList.Add(@{
            "id" = $i + 1;
            "url" = "/users/{$($usersToDisable[$i].id)}";
            "method" = "PATCH";
            "body" = @{
                "accountEnabled" = "false"
            };
            "headers" = @{
                "Content-Type" = "application/json"
            }
        }) | Out-Null
        
        # Appends JSON batch request to $batchRequests if a multiple of 20, or if the end of $usersToDisable has been reached
        if (($i + 1) % 20 -eq 0 -or $i -ge $usersToDisable.Count - 1)
        {
            $batchRequest.Add("requests", $requestsList)
            $batchRequests += $batchRequest | ConvertTo-Json -Depth 3
            
            Write-Output "[$(Get-Date -Format 'dd/MM/yyyy HH:mm:ss')] Built JSON batch request #$($batchRequests.Count), size: $($requestsList.Count)"
            
            $batchRequest = @{}
            $requestsList = New-Object System.Collections.ArrayList
        }
    }
    
    Write-Output "[$(Get-Date -Format 'dd/MM/yyyy HH:mm:ss')] Built JSON batch request(s)!"
    
    # Calls API for each batch request
    Write-Output "[$(Get-Date -Format 'dd/MM/yyyy HH:mm:ss')] Making API request(s)..."
    
    foreach ($jsonBatchRequest in $batchRequests)
    {
        Invoke-RestMethod -Method Post -Headers @{Authorization = "Bearer $($request.access_token)"} -Uri 'https://graph.microsoft.com/v1.0/$batch' -ContentType "application/json" -Body $jsonBatchRequest
    }
    
    Write-Output "[$(Get-Date -Format 'dd/MM/yyyy HH:mm:ss')] API requests made!"
    
    Write-Output "[$(Get-Date -Format 'dd/MM/yyyy HH:mm:ss')] User accounts disabled ($($usersToDisable.Count)):"
    foreach ($user in $usersToDisable)
    {
        Write-Output "[$(Get-Date -Format 'dd/MM/yyyy HH:mm:ss')] $($user.id) ($($user.displayName))"
    }
}
else
{
    Write-Output "[$(Get-Date -Format 'dd/MM/yyyy HH:mm:ss')] There are currently no users that fit the criteria, so no accounts have been disabled."
}

# Stops transcript
Stop-Transcript

EDIT 2: I'm not really sure what more information I can include here to help this question get answered. I would really appreciate some pointers from someone experienced in this area, cheers.

EDIT 3: Could really still do with this question being answered by someone who is half decent with PowerShell. Cheers.

Theosis
  • 11
  • 4
  • Can you post some of the code? It would be very difficult to diagnose without seeing any of the code that could be causing it. However, my first thought would be to check and see if you changed any global output verbosity preferences around that point in the execution. It's also sending back the responses object to the console so it looks like you have some unhandled outputs from a function somewhere – Efie Dec 20 '21 at 13:11
  • I've edited the post to include the whole code. – Theosis Dec 20 '21 at 16:57
  • Does the issue still happen if you comment out the ```Invoke-RestMethod``` line, or do you see the subsequent output in the transcript? Can you distill the code down to a smaller example that doesn't require calls to the Microsoft Graph API (e.g. a "GET" from google.com instead) so we can try to reproduce the issue locally? – mclayton Jan 18 '22 at 13:21
  • The issue does not happen if I comment out the "_POST_" `Invoke-RestMethod` line, because that is the thing that seems to be causing the issue; not the "GET" one. Using a "GET" request from google.com or such wouldn't reproduce the issue. It needs to be a "POST". – Theosis Jan 20 '22 at 11:59
  • Does POSTing to another test site cause the issue? Just trying to find a way to reproduce the issue here without a Graph api key. See https://stackoverflow.com/questions/5725430/http-test-server-accepting-get-post-requests for some example sites you could try POSTing to. – mclayton Jan 25 '22 at 22:52
  • Changing the URI in the POST to https://httpbin.org/anything seems to make the issue go away, implying that perhaps it's an issue with Graph (or how I'm interacting with it)? – Theosis Jan 28 '22 at 10:14

0 Answers0