Skip to content

[BUG] Sometimes CLion integration tests fail in CI #483

@vol0n

Description

@vol0n

Description
Sometimes CLion integration tests fail in workflow run.

To Reproduce
Could not reproduce it locally on my machine. To catch it in ci, launch the job Build UTBot and Run Integration Tests several times until clion tests fail.

Expected behavior
All tests must pass.

Actual behavior
Line tests fail with timeout exception. When plugin sends request to get project targets, server does not respond, and timeout exception is thrown.

Visual proofs (screenshots, logs)
Plugin logs:

20:51:16.755 | GenerateForLineTest.kt: 17 [AWT-EventQueue-0] |INFO| Testing generate for line using target: liblib.a, compiler: Clang, verbose mode: true, line: 3
    20:51:16.756 | CppCompiler.kt: 15 [AWT-EventQueue-0] |TRACE| Building the project with compiler: Clang, and build directory name: build
    20:51:16.757 | CppCompiler.kt: 16 [AWT-EventQueue-0] |TRACE| BUILD COMMAND: export CC=/utbot_distr/install/bin/clang && export CXX=/utbot_distr/install/bin/clang++ && mkdir -p build && cd build && /utbot_distr/install/bin/cmake .. && /utbot_distr/bear/bin/bear make -j8
    20:51:17.784 | CppCompiler.kt: 22 [AWT-EventQueue-0] |TRACE| BUILDING FINISHED!
    20:51:17.785 | BaseGenerationTestCase.kt: 98 [AWT-EventQueue-0] |INFO| Setting new target during test: liblib.a

GenerateForLineTest > test generate for line if in max function line() STANDARD_OUT
    20:51:17.8150 | Client.kt:72 [AWT-EventQueue-0 @coroutine#95] |INFO| Connecting to server on host: localhost , port: 2121 

    20:51:17.8152 | Client.kt:127 [AWT-EventQueue-0 @coroutine#95] |INFO| The heartbeat started with interval: 500 ms 

    20:51:17.8296 | Client.kt:147 [DefaultDispatcher-worker-7 @periodicHeartBeat#96] |INFO| Successfully connected to server! 

    20:51:17.8301 | Client.kt:118 [DefaultDispatcher-worker-5 @coroutine#98] |INFO| Sending REGISTER CLIENT request, clientID == user-62986 

    20:51:17.8307 | BaseRequest.kt:20 [DefaultDispatcher-worker-5 @Sending request to check project configuration.#99] |INFO| Sending request to check project configuration. 
    projectContext {
      projectName: "c-example-mini"
      projectPath: "/__w/UTBotCpp/UTBotCpp/integration-tests/c-example-mini"
      testDirPath: "/__w/UTBotCpp/UTBotCpp/integration-tests/c-example-mini/cl-plugin-test-tests"
      buildDirRelativePath: "build"
    }
 

    20:51:17.831 | LogChannelImpl.kt: 32 [DefaultDispatcher-worker-5 @GTest Log#100] |TRACE| Closing log channel: GTest Log
    20:51:17.832 | LogChannelImpl.kt: 32 [DefaultDispatcher-worker-5 @Server Log#101] |TRACE| Closing log channel: Server Log
    20:51:17.8362 | ProjectConfigurationHandler.kt:29 [DefaultDispatcher-worker-3 @Sending request to check project configuration.#99] |INFO| Received data in project config handler:  

    20:51:17.836 | LogChannelImpl.kt: 34 [DefaultDispatcher-worker-4 @GTest Log#100] |TRACE| Finished closing log channel: GTest Log
    20:51:17.836 | LogChannelImpl.kt: 39 [DefaultDispatcher-worker-4 @GTest Log#100] |TRACE| Opening log channel: GTest Log
    20:51:17.842 | LogChannelImpl.kt: 34 [DefaultDispatcher-worker-5 @Server Log#101] |TRACE| Finished closing log channel: Server Log
    20:51:17.842 | LogChannelImpl.kt: 39 [DefaultDispatcher-worker-5 @Server Log#101] |TRACE| Opening log channel: Server Log
    20:51:17.8469 | UTBotTargetsController.kt:91 [DefaultDispatcher-worker-7 @periodicHeartBeat#96] |TRACE| Requesting project targets from server! 

    20:51:17.8478 | ProjectTargetsRequest.kt:20 [DefaultDispatcher-worker-7 @Sending request to get project targets#108] |INFO| Before executing targets request! 

    20:51:17.8479 | BaseRequest.kt:20 [DefaultDispatcher-worker-7 @Sending request to get project targets#108] |INFO| Sending request to get project targets 
    projectContext {
      projectName: "c-example-mini"
      projectPath: "/__w/UTBotCpp/UTBotCpp/integration-tests/c-example-mini"
      testDirPath: "/__w/UTBotCpp/UTBotCpp/integration-tests/c-example-mini/cl-plugin-test-tests"
      buildDirRelativePath: "build"
    }
 

    20:51:18.815 | BaseGenerationTestCase.kt: 88 [AWT-EventQueue-0 @coroutine#95] |INFO| Waiting for connection to server!
    20:51:18.816 | BaseGenerationTestCase.kt: 93 [AWT-EventQueue-0 @coroutine#95] |INFO| Connected
    20:51:18.8166 | UTBotTargetsController.kt:91 [AWT-EventQueue-0] |TRACE| Requesting project targets from server! 

    20:51:18.816 | BaseGenerationTestCase.kt: 112 [AWT-EventQueue-0] |INFO| Started waiting for server requests!
    20:51:18.8170 | ProjectTargetsRequest.kt:20 [DefaultDispatcher-worker-7 @Sending request to get project targets#111] |INFO| Before executing targets request! 

    20:51:18.8171 | Client.kt:204 [AWT-EventQueue-0 @coroutine#112] |INFO| Started waiting for requests to finish!
     Unfinished: ["Sending request to get project targets#108":StandaloneCoroutine{Active}@caa3b3a, "Sending request to get project targets#111":StandaloneCoroutine{Active}@193a5f06]  

    20:51:18.8172 | BaseRequest.kt:20 [DefaultDispatcher-worker-7 @Sending request to get project targets#111] |INFO| Sending request to get project targets 
    projectContext {
      projectName: "c-example-mini"
      projectPath: "/__w/UTBotCpp/UTBotCpp/integration-tests/c-example-mini"
      testDirPath: "/__w/UTBotCpp/UTBotCpp/integration-tests/c-example-mini/cl-plugin-test-tests"
      buildDirRelativePath: "build"
    }
 
    20:52:55.998 | BaseGenerationTestCase.kt: 115 [AWT-EventQueue-0 @coroutine#112] |INFO| Waiting for requests to finish: ["Sending request to get project targets#108":StandaloneCoroutine{Active}@caa3b3a, "Sending request to get project targets#111":StandaloneCoroutine{Active}@193a5f06]
    20:52:56.999 | BaseGenerationTestCase.kt: 115 [AWT-EventQueue-0 @coroutine#112] |INFO| Waiting for requests to finish: ["Sending request to get project targets#108":StandaloneCoroutine{Active}@caa3b3a, "Sending request to get project targets#111":StandaloneCoroutine{Active}@193a5f06]
    20:52:58.000 | BaseGenerationTestCase.kt: 115 [AWT-EventQueue-0 @coroutine#112] |INFO| Waiting for requests to finish: ["Sending request to get project targets#108":StandaloneCoroutine{Active}@caa3b3a, "Sending request to get project targets#111":StandaloneCoroutine{Active}@193a5f06]
    20:52:59.001 | BaseGenerationTestCase.kt: 115 [AWT-EventQueue-0 @coroutine#112] |INFO| Waiting for requests to finish: ["Sending request to get project targets#108":StandaloneCoroutine{Active}@caa3b3a, "Sending request to get project targets#111":StandaloneCoroutine{Active}@193a5f06]
    20:53:00.001 | BaseGenerationTestCase.kt: 115 [AWT-EventQueue-0 @coroutine#112] |INFO| Waiting for requests to finish: ["Sending request to get project targets#108":StandaloneCoroutine{Active}@caa3b3a, "Sending request to get project targets#111":StandaloneCoroutine{Active}@193a5f06]
    20:53:01.002 | BaseGenerationTestCase.kt: 115 [AWT-EventQueue-0 @coroutine#112] |INFO| Waiting for requests to finish: ["Sending request to get project targets#108":StandaloneCoroutine{Active}@caa3b3a, "Sending request to get project targets#111":StandaloneCoroutine{Active}@193a5f06]
    20:53:02.003 | BaseGenerationTestCase.kt: 115 [AWT-EventQueue-0 @coroutine#112] |INFO| Waiting for requests to finish: ["Sending request to get project targets#108":StandaloneCoroutine{Active}@caa3b3a, "Sending request to get project targets#111":StandaloneCoroutine{Active}@193a5f06]
    20:53:03.003 | BaseGenerationTestCase.kt: 115 [AWT-EventQueue-0 @coroutine#112] |INFO| Waiting for requests to finish: ["Sending request to get project targets#108":StandaloneCoroutine{Active}@caa3b3a, "Sending request to get project targets#111":StandaloneCoroutine{Active}@193a5f06]
    20:53:04.004 | BaseGenerationTestCase.kt: 115 [AWT-EventQueue-0 @coroutine#112] |INFO| Waiting for requests to finish: ["Sending request to get project targets#108":StandaloneCoroutine{Active}@caa3b3a, "Sending request to get project targets#111":StandaloneCoroutine{Active}@193a5f06]
    20:53:05.005 | BaseGenerationTestCase.kt: 115 [AWT-EventQueue-0 @coroutine#112] |INFO| Waiting for requests to finish: ["Sending request to get project targets#108":StandaloneCoroutine{Active}@caa3b3a, "Sending request to get project targets#111":StandaloneCoroutine{Active}@193a5f06]
    20:53:06.006 | BaseGenerationTestCase.kt: 115 [AWT-EventQueue-0 @coroutine#112] |INFO| Waiting for requests to finish: ["Sending request to get project targets#108":StandaloneCoroutine{Active}@caa3b3a, "Sending request to get project targets#111":StandaloneCoroutine{Active}@193a5f06]
    20:53:07.006 | BaseGenerationTestCase.kt: 115 [AWT-EventQueue-0 @coroutine#112] |INFO| Waiting for requests to finish: ["Sending request to get project targets#108":StandaloneCoroutine{Active}@caa3b3a, "Sending request to get project targets#111":StandaloneCoroutine{Active}@193a5f06]
    20:53:08.007 | BaseGenerationTestCase.kt: 115 [AWT-EventQueue-0 @coroutine#112] |INFO| Waiting for requests to finish: ["Sending request to get project targets#108":StandaloneCoroutine{Active}@caa3b3a, "Sending request to get project targets#111":StandaloneCoroutine{Active}@193a5f06]
    20:53:09.008 | BaseGenerationTestCase.kt: 115 [AWT-EventQueue-0 @coroutine#112] |INFO| Waiting for requests to finish: ["Sending request to get project targets#108":StandaloneCoroutine{Active}@caa3b3a, "Sending request to get project targets#111":StandaloneCoroutine{Active}@193a5f06]
    20:53:10.008 | BaseGenerationTestCase.kt: 115 [AWT-EventQueue-0 @coroutine#112] |INFO| Waiting for requests to finish: ["Sending request to get project targets#108":StandaloneCoroutine{Active}@caa3b3a, "Sending request to get project targets#111":StandaloneCoroutine{Active}@193a5f06]

..........


    20:56:18.821 | BaseGenerationTestCase.kt: 122 [Test worker] |INFO| tearDown is called!

GenerateForLineTest > test generate for line if in max function line() FAILED
    kotlinx.coroutines.TimeoutCancellationException: Timed out waiting for 300000 ms
        at ���(Coroutine boundary.�(�)
        at org.utbot.cpp.clion.plugin.client.Client$waitForServerRequestsToFinish$2$1.invokeSuspend(Client.kt:207)
        at org.utbot.cpp.clion.plugin.client.Client$waitForServerRequestsToFinish$2.invokeSuspend(Client.kt:203)

        Caused by:
        kotlinx.coroutines.TimeoutCancellationException: Timed out waiting for 300000 ms
            at app//kotlinx.coroutines.TimeoutKt.TimeoutCancellationException(Timeout.kt:186)
            at app//kotlinx.coroutines.TimeoutCoroutine.run(Timeout.kt:156)
            at app//kotlinx.coroutines.EventLoopImplBase$DelayedRunnableTask.run(EventLoop.common.kt:497)
            at app//kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:274)
            at app//kotlinx.coroutines.DefaultExecutor.run(DefaultExecutor.kt:69)
            at [email protected]/java.lang.Thread.run(Thread.java:829)

Server logs for corresponding client (everything.log):

File verbosity level: 9
date       time         [ thread name/id ]                   file:line     v| 
2022-09-29 20:51:17.845 [user-62986      ]             loguru.cpp:770   INFO| Logging to '/github/home/logs/user-62986/everything.log', mode: 'a', verbosity: 9
2022-09-29 20:51:17.846 [user-62986      ]             loguru.cpp:770   INFO| Logging to '/github/home/logs/user-62986/latest_readable.log', mode: 'w', verbosity: 0
2022-09-29 20:51:17.851 [        7CC1C700]             Server.cpp:647   INFO| GetProjectTargets receive:
projectContext {
  projectName: "c-example-mini"
  projectPath: "/__w/UTBotCpp/UTBotCpp/integration-tests/c-example-mini"
  testDirPath: "/__w/UTBotCpp/UTBotCpp/integration-tests/c-example-mini/cl-plugin-test-tests"
  buildDirRelativePath: "build"
}

2022-09-29 20:51:17.851 [user-62986      ]             Server.cpp:657   INFO| Creating shared pointer to project build database
2022-09-29 20:51:17.851 [user-62986      ]   CompilationUtils.cpp:117      1| compile_commands.json for mount is written to: "/__w/UTBotCpp/UTBotCpp/integration-tests/c-example-mini/build/utbot_build"
2022-09-29 20:51:17.852 [user-62986      ]   CompilationUtils.cpp:117      1| link_commands.json for mount is written to: "/__w/UTBotCpp/UTBotCpp/integration-tests/c-example-mini/build/utbot_build"

Environment
same as in CI

Additional context

Metadata

Metadata

Assignees

Labels

bugSomething isn't workingclion-pluginIssue related to CLion plugin

Type

No type

Projects

Status

Todo

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions