Uploaded image for project: 'Debezium'
  1. Debezium
  2. DBZ-6877

Intermittent test failure on SQL Server CI

XMLWordPrintable

    • Icon: Task Task
    • Resolution: Obsolete
    • Icon: Major Major
    • None
    • None
    • sqlserver-connector
    • None
    • False
    • Hide

      None

      Show
      None
    • False

      Observed two different kinds of failure on the SQL Server CI for several PRs (main & PR branches) running too long (6h) and failing/cancelled.
      Failure 1 on PR #7113

      [io.debezium.pipeline.source.snapshot.incremental.AbstractIncrementalSnapshotContext]
      2023-09-07 09:14:34,404 INFO   SQL_Server|server1|0|streaming|testDB1  Incremental snapshot for table 'testDB1.dbo.a' will end at position [1000]   [io.debezium.pipeline.source.snapshot.incremental.AbstractIncrementalSnapshotChangeEventSource]
      09:14:54.429 sqlserver
      getspinlock pre-Sleep(): spid 0, 4022 yields on lock type "XDESMGR" (adr 0000000F8DFB96C0)
      09:14:56.742 sqlserver
      getspinlock pre-Sleep(): spid 0, 4000 yields on lock type "XDESMGR" (adr 0000000F8DFB96C0)
      .. 
      ..
      getspinlock pre-Sleep(): spid 0, 4183957 yields on lock type "XDESMGR" (adr 0000000F8DFB96C0)
      15:03:06.999 sqlserver
      getspinlock pre-Sleep(): spid 0, 4182652 yields on lock type "XDESMGR" (adr 0000000F8DFB96C0)
      15:03:07.997 sqlserver
      2023-09-07 20:48:07.97 Server      Process 0:0:0 (0x22c) Worker 0x0000000F85EF0160 appears to be non-yielding on Scheduler 0. Thread creation time: 13338551134169. Approx Thread CPU Used: kernel 31730 ms, user 18118650 ms. Process Utilization 87%. System Idle 0%. Interval: 20904325 ms.
      15:03:08.019 sqlserver
      2023-09-07 20:48:07.99 Server      Process 0:0:0 (0x344) Worker 0x0000000F93328160 appears to be non-yielding on Scheduler 1. Thread creation time: 13338551254836. Approx Thread CPU Used: kernel 32590 ms, user 18111920 ms. Process Utilization 87%. System Idle 0%. Interval: 20904349 ms.
      Error: The operation was canceled.
      

      Failure 2 on PR #7119

      2023-09-07 21:18:26,118 ERROR  SqlServerConnectorIT|||engine|  Error while trying to run connector class 'io.debezium.connector.sqlserver.SqlServerConnector'   [io.debezium.connector.sqlserver.SqlServerConnectorIT]
      org.apache.kafka.connect.errors.ConnectException: An exception occurred in the change event producer. This connector will be stopped.
      	at io.debezium.pipeline.ErrorHandler.setProducerThrowable(ErrorHandler.java:67)
      	at io.debezium.pipeline.ChangeEventSourceCoordinator.lambda$start$0(ChangeEventSourceCoordinator.java:144)
      	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
      	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
      	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
      	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
      	at java.base/java.lang.Thread.run(Thread.java:833)
      Caused by: io.debezium.DebeziumException: com.microsoft.sqlserver.jdbc.SQLServerException: Database 'testDB2' is in transition. Try the statement later.
      	at io.debezium.pipeline.source.AbstractSnapshotChangeEventSource.execute(AbstractSnapshotChangeEventSource.java:101)
      	at io.debezium.pipeline.ChangeEventSourceCoordinator.doSnapshot(ChangeEventSourceCoordinator.java:253)
      	at io.debezium.pipeline.ChangeEventSourceCoordinator.doSnapshot(ChangeEventSourceCoordinator.java:237)
      	at io.debezium.connector.sqlserver.SqlServerChangeEventSourceCoordinator.executeChangeEventSources(SqlServerChangeEventSourceCoordinator.java:82)
      	at io.debezium.pipeline.ChangeEventSourceCoordinator.lambda$start$0(ChangeEventSourceCoordinator.java:137)
      	... 5 common frames omitted
      Caused by: com.microsoft.sqlserver.jdbc.SQLServerException: Database 'testDB2' is in transition. Try the statement later.
      	at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDatabaseError(SQLServerException.java:265)
      	at com.microsoft.sqlserver.jdbc.TDSTokenHandler.onEOF(tdsparser.java:299)
      	at com.microsoft.sqlserver.jdbc.TDSParser.parse(tdsparser.java:132)
      	at com.microsoft.sqlserver.jdbc.TDSParser.parse(tdsparser.java:37)
      	at com.microsoft.sqlserver.jdbc.TDSParser.parse(tdsparser.java:26)
      	at com.microsoft.sqlserver.jdbc.SQLServerConnection$1ConnectionCommand.doExecute(SQLServerConnection.java:3897)
      	at com.microsoft.sqlserver.jdbc.TDSCommand.execute(IOBuffer.java:7730)
      	at com.microsoft.sqlserver.jdbc.SQLServerConnection.executeCommand(SQLServerConnection.java:3786)
      	at com.microsoft.sqlserver.jdbc.SQLServerConnection.connectionCommand(SQLServerConnection.java:3905)
      	at com.microsoft.sqlserver.jdbc.SQLServerConnection.setCatalog(SQLServerConnection.java:4271)
      	at com.microsoft.sqlserver.jdbc.SQLServerDatabaseMetaData.switchCatalogs(SQLServerDatabaseMetaData.java:400)
      	at com.microsoft.sqlserver.jdbc.SQLServerDatabaseMetaData.getResultSetFromStoredProc(SQLServerDatabaseMetaData.java:349)
      	at com.microsoft.sqlserver.jdbc.SQLServerDatabaseMetaData.getResultSetWithProvidedColumnNames(SQLServerDatabaseMetaData.java:374)
      	at com.microsoft.sqlserver.jdbc.SQLServerDatabaseMetaData.getTables(SQLServerDatabaseMetaData.java:561)
      	at io.debezium.jdbc.JdbcConnection.readTableNames(JdbcConnection.java:1058)
      	at io.debezium.connector.sqlserver.SqlServerSnapshotChangeEventSource.getAllTableIds(SqlServerSnapshotChangeEventSource.java:114)
      	at io.debezium.relational.RelationalSnapshotChangeEventSource.determineCapturedTables(RelationalSnapshotChangeEventSource.java:279)
      	at io.debezium.relational.RelationalSnapshotChangeEventSource.doExecute(RelationalSnapshotChangeEventSource.java:134)
      	at io.debezium.pipeline.source.AbstractSnapshotChangeEventSource.execute(AbstractSnapshotChangeEventSource.java:92)
      	... 9 common frames omitted
      21:19:25.794 sqlserver
      2023-09-08 03:04:25.79 Logon       Error: 18456, Severity: 14, State: 38.
      21:19:25.798 sqlserver
      2023-09-08 03:04:25.79 Logon       Login failed for user 'NT AUTHORITY\NETWORK SERVICE'. Reason: Failed to open the explicitly specified database 'testDB2'. [CLIENT: 172.17.0.2]
      21:20:25.827 sqlserver
      ..
      ..
      2023-09-08 03:12:26.04 Logon       Error: 18456, Severity: 14, State: 38.
      21:27:26.047 sqlserver
      2023-09-08 03:12:26.04 Logon       Login failed for user 'NT AUTHORITY\NETWORK SERVICE'. Reason: Failed to open the explicitly specified database 'testDB2'. [CLIENT: 172.17.0.2]
      21:28:26.081 sqlserver
      2023-09-08 03:13:26.07 Logon       Error: 18456, Severity: 14, State: 38.
      21:28:26.083 sqlserver
      2023-09-08 03:13:26.07 Logon       Login failed for user 'NT AUTHORITY\NETWORK SERVICE'. Reason: Failed to open the explicitly specified database 'testDB2'. [CLIENT: 172.17.0.2]
      Error: The operation was canceled.
      

              Unassigned Unassigned
              anmohant Anisha Mohanty (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

                Created:
                Updated:
                Resolved: