Process does not exit

[defenestration]

Hello,

We've noticed once in a while that sqlcmd does not exit properly though the scripts we run seem to complete.

We run in a kubernetes cronjob as part of a larger script. We are connecting to a db in Azure Sql. We can see in ps that the sqlcmd process is still active on the pod:

sqlcmd -b -r 1 -h -1 -i ../sql/UpdateStatistics.sql -N true -S tcp:tscMYDB-fg-dev1.database.windows.net,1433 -d tscMYDB-dev1 -G -v p_MaxDaysSinceUpdate=7 -v p_MinimumIndexPageCountToUpdate=10 -v p_IsDebug=0 --driver-logging-level 64

It doesn't seem to be a bug in the script, and we are unable to reproduce consistently as well.

We also have a different script that hit the same issue, but do not have debug logs from that occurrence.

We had have a similar issue in v1.6.0 so we have since updated to 1.8.2, but the issue persists.

If needed, can provide the full logs.

See script/logs below.

Last few lines of log from the pod with timestamps:

2025-03-25T20:23:34.971729666Z Updated statistics with full scan: [MYDB].[Review].[IX_Review_MasterReviewId] was previously updated on 2025-03-18 20:22:05, table had 357631 rows at time of last update, and table now has 358233 rows.                                                                                                                                                                                                                                                                                                                                                                                 
2025-03-25T20:23:34.971766032Z DRIVER:Next() token type:mssql.doneStruct
2025-03-25T20:23:34.971777421Z 
2025-03-25T20:23:34.971784485Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.971789207Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.971793543Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.971797928Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.971814668Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.971821741Z DRIVER:got token tokenDone
2025-03-25T20:23:34.971828031Z DRIVER:got DONE or DONEPROC status=1
2025-03-25T20:23:34.971834952Z DRIVER:got token tokenDone
2025-03-25T20:23:34.971840969Z DRIVER:got DONE or DONEPROC status=1
2025-03-25T20:23:34.971852038Z DRIVER:got token tokenReturnStatus
2025-03-25T20:23:34.971871611Z DRIVER:got token tokenDoneProc
2025-03-25T20:23:34.971878240Z DRIVER:got DONE or DONEPROC status=1
2025-03-25T20:23:34.971884507Z DRIVER:got token tokenDone
2025-03-25T20:23:34.971890731Z DRIVER:got DONE or DONEPROC status=1
2025-03-25T20:23:34.971897859Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.971904923Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.971911615Z DRIVER:NextResultSet() token type:mssql.ReturnStatus
2025-03-25T20:23:34.971919715Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.971925967Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.971932226Z DRIVER:got token tokenDone
2025-03-25T20:23:34.971938273Z DRIVER:got DONE or DONEPROC status=1
2025-03-25T20:23:34.971944836Z DRIVER:got token tokenDone
2025-03-25T20:23:34.971951200Z DRIVER:got DONE or DONEPROC status=1
2025-03-25T20:23:34.971957685Z DRIVER:got token tokenDone
2025-03-25T20:23:34.971970184Z DRIVER:got DONE or DONEPROC status=1
2025-03-25T20:23:34.972028090Z DRIVER:got token tokenColMetadata
2025-03-25T20:23:34.972039288Z DRIVER:got token tokenRow
2025-03-25T20:23:34.972045726Z DRIVER:got token tokenDone
2025-03-25T20:23:34.972054734Z DRIVER:got DONE or DONEPROC status=1
2025-03-25T20:23:34.972077000Z DRIVER:got token tokenDone
2025-03-25T20:23:34.972084706Z DRIVER:got DONE or DONEPROC status=1DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.972091178Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.972097435Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.972103800Z DRIVER:NextResultSet() token type:[]mssql.columnStruct
2025-03-25T20:23:34.972109982Z DRIVER:Next() token type:[]interface {}
2025-03-25T20:23:34.972115841Z 
2025-03-25T20:23:34.972122222Z DRIVER:got token tokenDone
2025-03-25T20:23:34.972129051Z DRIVER:got DONE or DONEPROC status=1
2025-03-25T20:23:34.972135394Z DRIVER:got token tokenDone
2025-03-25T20:23:34.972141811Z DRIVER:got DONE or DONEPROC status=1
2025-03-25T20:23:34.972157376Z DRIVER:got token tokenDone
2025-03-25T20:23:34.972164109Z DRIVER:got DONE or DONEPROC status=1
2025-03-25T20:23:34.972170577Z DRIVER:got token tokenDone
2025-03-25T20:23:34.972176835Z DRIVER:got DONE or DONEPROC status=1
2025-03-25T20:23:34.972515030Z Updated statistics with full scan: [MYDB].[Comment].[UX_Comment_CommentExternalId] was previously updated on 2025-03-18 20:22:25, table had 135151 rows at time of last update, and table now has 135203 rows.                                                                                                                                                                                                                                                                                                                                                                            
2025-03-25T20:23:34.972549575Z DRIVER:Next() token type:mssql.doneStruct
2025-03-25T20:23:34.972556105Z 
2025-03-25T20:23:34.972562442Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.972568335Z DRIVER:got token tokenColMetadata
2025-03-25T20:23:34.972573910Z DRIVER:got token tokenRow
2025-03-25T20:23:34.972579990Z DRIVER:got token tokenDone
2025-03-25T20:23:34.972587376Z DRIVER:got DONE or DONEPROC status=0
2025-03-25T20:23:34.972591586Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.972595596Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.972599478Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.972603408Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.972607373Z DRIVER:NextResultSet() token type:[]mssql.columnStruct
2025-03-25T20:23:34.972621730Z DRIVER:Next() token type:[]interface {}
2025-03-25T20:23:34.972629002Z Started At: 2025-03-25 20:23:11 Ended At: 2025-03-25 20:23:35 Total Execution Time in Minutes: 0                     
2025-03-25T20:23:34.972636954Z DRIVER:Next() token type:mssql.doneStruct
2025-03-25T20:23:34.972802764Z DRIVER:got token tokenDone
2025-03-25T20:23:34.972815006Z DRIVER:got DONE or DONEPROC status=32
2025-03-25T20:23:34.972824867Z 

UpdateStatistics.sql

DECLARE
    @v_IsDebug AS BIT
   ,@v_MaxDaysSinceUpdate AS INT
   ,@v_MinimumIndexPageCountToUpdate AS INT
   ,@v_DatabaseName AS SYSNAME
   ,@v_StartTime AS DATETIME2(0)
   ,@v_StopTime AS DATETIME2(0)
   ,@v_OperationStartTime AS DATETIME2(0)
   ,@v_OperationStopTime AS DATETIME2(0)
   ,@v_EmailSubject AS NVARCHAR(255)
   ,@v_QueriesExecuted AS NVARCHAR(MAX)
   ,@v_NewLine AS CHAR(2) = CHAR(13)+CHAR(10)
   ,@v_StaleStatisticsCutoffTime DATETIME2(0)
   ,@v_ErrorMessage AS NVARCHAR(4000);

-- Table variable to store the statistics that are in need of maintenance
DECLARE @v_StaleStatisticsInformationTable AS TABLE
   (  
       StatisticsMaintenanceId INT IDENTITY( 1,1 )
      ,SchemaName SYSNAME
      ,TableId INT
      ,TableName SYSNAME
      ,IndexId INT
      ,IndexName SYSNAME NULL -- Heaps do not have an index name
      ,StatsLastUpdatedTime DATETIME2(0)
      ,RowCountOnLastStatsUpdate BIGINT
   );

BEGIN
   SET @v_IsDebug = $(p_IsDebug);
   SET @v_MaxDaysSinceUpdate = $(p_MaxDaysSinceUpdate);
   SET @v_MinimumIndexPageCountToUpdate = $(p_MinimumIndexPageCountToUpdate);
   SET @v_DatabaseName = DB_NAME();
   SET @v_StartTime = GETDATE();

   SET NOCOUNT ON; -- Removes affected row count

   -- Before doing anything, validate that the database exists.  This should
   -- prevent any SQL Injection attacks
   IF DB_ID( @v_DatabaseName ) IS NULL
   BEGIN
      SET @v_ErrorMessage = 'Database not found: ' + @v_DatabaseName;
      THROW 50000, @v_ErrorMessage, 1;
   END;

   SELECT 'Statistics Maintenance Sproc report for server ' + @@SERVERNAME + ' on database: ' + @v_DatabaseName;
   SELECT @v_EmailSubject = @@SERVERNAME + ' ' + @v_DatabaseName + ' Statistics Report';

   -- Enabling debugging mode for additional details in email report
   IF @v_IsDebug <> 1 AND @v_IsDebug <> 0
      SET @v_IsDebug = 0
   SET @v_QueriesExecuted = '';

   IF @v_MaxDaysSinceUpdate < 0
   BEGIN
      SET @v_ErrorMessage = 'v_MaxDaysSinceUpdate must be greater than or equal to 0. Was ' + CAST( @v_MaxDaysSinceUpdate AS VARCHAR(20) );
      THROW 50001, @v_ErrorMessage, 1;
   END

   IF @v_MinimumIndexPageCountToUpdate < 0
   BEGIN
      SET @v_ErrorMessage = 'v_MinimumIndexPageCountToUpdate must be greater than or equal to 0. Was ' + CAST( @v_MinimumIndexPageCountToUpdate AS VARCHAR(20) );
      THROW 50002, @v_ErrorMessage, 1;
   END

   SET @v_StaleStatisticsCutoffTime = DATEADD(DAY, -@v_MaxDaysSinceUpdate, GETDATE());

   -- Find statistics that need to be updated
   DECLARE @v_GetStaleStatisticsCmd NVARCHAR(MAX);
   SET @v_GetStaleStatisticsCmd = '
      SELECT
          s.name AS SchemaName
         ,o.object_id AS TableId
         ,o.name AS TableName
         ,i.index_id AS IndexId
         ,i.name AS IndexName
         ,stats_props.last_updated AS StatsLastUpdatedTime
         ,stats_props.unfiltered_rows AS RowCountOnLastStatsUpdate
      FROM
         ['+ @v_DatabaseName +'].sys.stats AS stats
      INNER JOIN
         ['+ @v_DatabaseName +'].sys.objects AS o ON o.object_id = stats.object_id
      INNER JOIN
         ['+ @v_DatabaseName +'].sys.schemas AS s ON s.schema_id = o.schema_id
      INNER JOIN
         ['+ @v_DatabaseName +'].sys.indexes AS i ON i.object_id = o.object_id AND stats.stats_id = i.index_id -- Stats ID corresponds to index ID when stats are for an index
      INNER JOIN
         ['+ @v_DatabaseName +'].INFORMATION_SCHEMA.TABLES AS t ON t.TABLE_SCHEMA = s.name AND t.TABLE_NAME = o.name AND t.TABLE_TYPE = ''BASE TABLE'' -- Remove system tables from list
      CROSS APPLY
         sys.dm_db_stats_properties(o.object_id, stats.stats_id) AS stats_props
      CROSS APPLY
         sys.dm_db_index_physical_stats( DB_ID( '''+ @v_DatabaseName + ''' ) , o.object_id, i.index_id, NULL, ''LIMITED'') AS phys_stats
      WHERE
         i.auto_created = 0
      AND
         stats.auto_created = 0
      AND
         (stats_props.last_updated IS NULL
      OR
         stats_props.last_updated <= @v_StaleStatisticsCutoffTime)
      AND
         -- Indexes with less than the specified number of page files are not big enough to worry about
         phys_stats.page_count >= ' + CAST( @v_MinimumIndexPageCountToUpdate AS VARCHAR(20) ) + '
      ORDER BY
         stats_props.last_updated
      ASC';

   SET @v_OperationStartTime = GETDATE();

   BEGIN TRY
      INSERT INTO @v_StaleStatisticsInformationTable EXECUTE sp_executesql @v_GetStaleStatisticsCmd
      ,N'@v_StaleStatisticsCutoffTime DATETIME2(0)'
      ,@v_StaleStatisticsCutoffTime = @v_StaleStatisticsCutoffTime;
   END TRY
   BEGIN CATCH
      SET @v_ErrorMessage = 'Failed to query statistics in need of update: ' + ERROR_MESSAGE();
      THROW 50003, @v_ErrorMessage, 1;
   END CATCH;

   SELECT @v_QueriesExecuted = @v_QueriesExecuted + @v_NewLine + @v_NewLine + 'Get stale statistics info command: ' + @v_GetStaleStatisticsCmd;

   SET @v_OperationStopTime = GETDATE();

   SELECT 'Finished querying for statistics in need of update. ' + 'Started At: ' + CAST( @v_OperationStartTime AS VARCHAR(20) ) + ' Ended At: ' + CAST( @v_OperationStopTime AS VARCHAR(20) ) + ' Took ' + CAST( DATEDIFF( SECOND, @v_OperationStartTime, @v_OperationStopTime ) AS VARCHAR(20) )  + ' seconds';

   DECLARE
       @v_CurSchema AS SYSNAME
      ,@v_CurTableId AS INT
      ,@v_CurTableName AS SYSNAME
      ,@v_CurIndexId AS INT
      ,@v_CurIndexName AS SYSNAME
      ,@v_CurStatsLastUpdatedTime AS DATETIME2(0)
      ,@v_CurRowCountOnLastStatsUpdate AS BIGINT
      ,@v_CurCurrentRowCount AS BIGINT
      ,@v_Counter AS SMALLINT
      ,@v_LastRow AS SMALLINT
      ,@v_UpdateStatisticsCmd AS NVARCHAR(MAX)

   SET @v_Counter = 1;
   SELECT @v_LastRow = COUNT(1) FROM @v_StaleStatisticsInformationTable;

   -- Loop through the statistics and force a full scan
   WHILE ( @v_Counter <= @v_LastRow )
   BEGIN
      SELECT
          @v_CurSchema = '[' + s.SchemaName + ']'
         ,@v_CurTableId = s.TableId
         ,@v_CurTableName = '[' + s.TableName + ']'
         ,@v_CurIndexId = s.IndexId
         ,@v_CurIndexName = '[' + s.IndexName + ']'
         ,@v_CurStatsLastUpdatedTime = s.StatsLastUpdatedTime
         ,@v_CurRowCountOnLastStatsUpdate = s.RowCountOnLastStatsUpdate
      FROM
         @v_StaleStatisticsInformationTable AS s
      WHERE
         s.StatisticsMaintenanceId = @v_Counter;

      BEGIN TRY
         SET @v_OperationStartTime = GETDATE();
         SET @v_UpdateStatisticsCmd = 'UPDATE STATISTICS ' + @v_CurSchema + '.' + @v_CurTableName + ' ' + @v_CurIndexName + ' WITH FULLSCAN';
         EXECUTE sp_executesql @v_UpdateStatisticsCmd;
         SET @v_OperationStopTime = GETDATE();

         SELECT @v_QueriesExecuted = @v_QueriesExecuted + @v_NewLine + @v_UpdateStatisticsCmd;

         SELECT @v_CurCurrentRowCount = stats_props.unfiltered_rows
         FROM sys.dm_db_stats_properties(@v_CurTableId, @v_CurIndexId) AS stats_props

         IF @v_CurCurrentRowCount IS NULL
         BEGIN
            SET @v_CurCurrentRowCount = 0
         END
         SELECT 'Updated statistics with full scan: ' + @v_CurSchema + '.' + @v_CurTableName + '.' + @v_CurIndexName + ' was previously updated on ' + CASE WHEN @v_CurStatsLastUpdatedTime IS NULL THEN 'NEVER' ELSE CAST( @v_CurStatsLastUpdatedTime AS VARCHAR(20) ) END + ', table had ' + CASE WHEN @v_CurRowCountOnLastStatsUpdate IS NULL THEN '0' ELSE CAST( @v_CurRowCountOnLastStatsUpdate AS VARCHAR(20) ) END + ' rows at time of last update, and table now has ' + CAST( @v_CurCurrentRowCount AS VARCHAR(20) ) + ' rows.';
      END TRY
      BEGIN CATCH
         SET @v_ErrorMessage = 'Failed to execute statistics full scan statement: ' + @v_UpdateStatisticsCmd + '. Due to exception: ' + ERROR_MESSAGE();
         THROW 50004, @v_ErrorMessage, 1;
      END CATCH

      SET @v_Counter = @v_Counter + 1;
   END;

   -- Assemble the debugging output and append if enabled
   IF @v_IsDebug = 1
   BEGIN
      SELECT 'Debug Output Enabled' + @v_NewLine + @v_NewLine + '---------------------' + @v_NewLine + @v_NewLine + @v_QueriesExecuted;
   END;

   -- Email sproc results
   SET @v_StopTime = GETDATE();
   SELECT 'Started At: ' + CAST( @v_StartTime AS VARCHAR(20) ) + ' Ended At: ' + CAST( @v_StopTime AS VARCHAR(20) ) + ' Total Execution Time in Minutes: ' + CAST( DATEDIFF( MINUTE, @v_StartTime, @v_StopTime ) AS VARCHAR(20) );
END;
GO

[shueybubbles]

I wonder if it might be related to #581

[PaulStanos]

I wonder if it might be related to #581

Hi @shueybubbles. @defenestration and I published a change to remove the GO command from the end of the script, as well as the unnecessary BEGIN and END that wraps most of the commands in our script.

Given that this isn't easy to reproduce, it might take a few days to know if this has had the desired effect. I'll check back in then!