Open milismsft opened 2 years ago
@kntajus I was interested in knowing the emulator startup script. With your comment it looks like that you are not facing problem with Emulator startup but after successful startup some operation fails which causes test failure. If that's true, then we would need emulator logs to debug further.
Hi @niteshvijay1995,
We had a failure yesterday (in addition to a few more builds which were fine).
Machine information for failed build Example of error of failing test Diff of the machine information
@JonathanLydall Can you please confirm if the emulator startup is failing in failed build? Please share logs from docker. It should start with
This is an evaluation version. There are [x] days left in the evaluation period.
Starting
Started 1/11 partitions
@niteshvijay1995, there is no text like that in the logs for the run, but only some of the tests against Cosmos DB are failing, not all.
Below is the start of the logs for the dotnet test
execution. Of particular note you will see many requests succeed Like POSTs and GETs to /api/customer/<sub-path>
, these endpoints are using Cosmos, meaning that the container is working for those tests, but then later fails.
```
2024-07-08T13:49:57.9960387Z ##[section]Starting: dotnet test
2024-07-08T13:49:57.9968976Z ==============================================================================
2024-07-08T13:49:57.9969129Z Task : .NET Core
2024-07-08T13:49:57.9969220Z Description : Build, test, package, or publish a dotnet application, or run a custom dotnet command
2024-07-08T13:49:57.9969360Z Version : 2.242.0
2024-07-08T13:49:57.9969430Z Author : Microsoft Corporation
2024-07-08T13:49:57.9969543Z Help : https://docs.microsoft.com/azure/devops/pipelines/tasks/build/dotnet-core-cli
2024-07-08T13:49:57.9969671Z ==============================================================================
2024-07-08T13:49:58.6636365Z Info: .NET Core SDK/runtime 2.2 and 3.0 are now End of Life(EOL) and have been removed from all hosted agents. If you're using these SDK/runtimes on hosted agents, kindly upgrade to newer versions which are not EOL, or else use UseDotNet task to install the required version.
2024-07-08T13:50:05.0632307Z [command]/usr/bin/dotnet test /home/vsts/work/1/s/InternalTestModules/Intent.Modules.NET.InternalTestModules.sln --logger trx --results-directory /home/vsts/work/_temp --no-build
2024-07-08T13:50:05.0638143Z [command]/usr/bin/dotnet test /home/vsts/work/1/s/Modules.Archived/Google PubSub/Publish.AspNetCore.GooglePubSub.TestApplication/Publish.AspNetCore.GooglePubSub.TestApplication.sln --logger trx --results-directory /home/vsts/work/_temp --no-build
2024-07-08T13:50:06.0468588Z [command]/usr/bin/dotnet test /home/vsts/work/1/s/Modules.Archived/Google PubSub/Publish.CleanArch.GooglePubSub.TestApplication/Publish.CleanArch.GooglePubSub.TestApplication.sln --logger trx --results-directory /home/vsts/work/_temp --no-build
2024-07-08T13:50:07.7571689Z [command]/usr/bin/dotnet test /home/vsts/work/1/s/Modules.Archived/Google PubSub/Subscribe.GooglePubSub.TestApplication/Subscribe.GooglePubSub.TestApplication.sln --logger trx --results-directory /home/vsts/work/_temp --no-build
2024-07-08T13:50:09.3437852Z [command]/usr/bin/dotnet test /home/vsts/work/1/s/Modules/Intent.Modules.NET.sln --logger trx --results-directory /home/vsts/work/_temp --no-build
2024-07-08T13:50:11.0561647Z Test run for /home/vsts/work/1/s/Modules/Intent.Modules.VisualStudio.Projects.Tests/bin/Debug/net8.0/Intent.Modules.VisualStudio.Projects.Tests.dll (.NETCoreApp,Version=v8.0)
2024-07-08T13:50:11.1849442Z Microsoft (R) Test Execution Command Line Tool Version 17.10.0 (x64)
2024-07-08T13:50:11.1850304Z Copyright (c) Microsoft Corporation. All rights reserved.
2024-07-08T13:50:11.1922540Z
2024-07-08T13:50:11.4518071Z Starting test execution, please wait...
2024-07-08T13:50:11.5236195Z A total of 1 test files matched the specified pattern.
2024-07-08T13:50:15.9299083Z Results File: /home/vsts/work/_temp/_fv-az368-975_2024-07-08_13_50_15.trx
2024-07-08T13:50:15.9312202Z
2024-07-08T13:50:15.9390251Z Passed! - Failed: 0, Passed: 41, Skipped: 0, Total: 41, Duration: 595 ms - Intent.Modules.VisualStudio.Projects.Tests.dll (net8.0)
2024-07-08T13:50:18.5373669Z [command]/usr/bin/dotnet test /home/vsts/work/1/s/Tests/AdvancedMappingCrud.Cosmos.Tests/AdvancedMappingCrud.Cosmos.Tests.sln --logger trx --results-directory /home/vsts/work/_temp --no-build
2024-07-08T13:50:19.8734917Z Test run for /home/vsts/work/1/s/Tests/AdvancedMappingCrud.Cosmos.Tests/AdvancedMappingCrud.Cosmos.Tests.IntegrationTests/bin/Debug/net8.0/AdvancedMappingCrud.Cosmos.Tests.IntegrationTests.dll (.NETCoreApp,Version=v8.0)
2024-07-08T13:50:19.9902808Z Microsoft (R) Test Execution Command Line Tool Version 17.10.0 (x64)
2024-07-08T13:50:19.9909009Z Copyright (c) Microsoft Corporation. All rights reserved.
2024-07-08T13:50:20.0069168Z
2024-07-08T13:50:20.1646330Z Starting test execution, please wait...
2024-07-08T13:50:20.2173070Z A total of 1 test files matched the specified pattern.
2024-07-08T13:50:24.7635655Z [testcontainers.org 00:00:00.13] Connected to Docker:
2024-07-08T13:50:24.7636785Z Host: unix:///var/run/docker.sock
2024-07-08T13:50:24.7637861Z Server Version: 26.1.3
2024-07-08T13:50:24.7639823Z Kernel Version: 6.5.0-1022-azure
2024-07-08T13:50:24.7640686Z API Version: 1.45
2024-07-08T13:50:24.7641095Z Operating System: Ubuntu 22.04.4 LTS
2024-07-08T13:50:24.7641750Z Total Memory: 6.76 GB
2024-07-08T13:50:24.8229689Z [testcontainers.org 00:00:00.18] Searching Docker registry credential in Auths
2024-07-08T13:50:24.8235495Z [testcontainers.org 00:00:00.18] Searching Docker registry credential in CredHelpers
2024-07-08T13:50:24.8247134Z [testcontainers.org 00:00:00.19] Searching Docker registry credential in CredsStore
2024-07-08T13:50:24.8265303Z [testcontainers.org 00:00:00.19] Docker registry credential https://index.docker.io/v1/ found
2024-07-08T13:50:27.0913128Z [testcontainers.org 00:00:02.45] Docker image testcontainers/ryuk:0.6.0 created
2024-07-08T13:50:27.1920096Z [testcontainers.org 00:00:02.55] Docker container 2d2ae6048c84 created
2024-07-08T13:50:27.2553369Z [testcontainers.org 00:00:02.62] Start Docker container 2d2ae6048c84
2024-07-08T13:50:27.7320718Z [testcontainers.org 00:00:03.09] Wait for Docker container 2d2ae6048c84 to complete readiness checks
2024-07-08T13:50:27.7449018Z [testcontainers.org 00:00:03.11] Docker container 2d2ae6048c84 ready
2024-07-08T13:50:27.7704805Z [testcontainers.org 00:00:03.13] Searching Docker registry credential in Auths
2024-07-08T13:50:27.7708658Z [testcontainers.org 00:00:03.13] Searching Docker registry credential in Auths
2024-07-08T13:50:27.7714613Z [testcontainers.org 00:00:03.13] Searching Docker registry credential in CredHelpers
2024-07-08T13:50:27.7715750Z [testcontainers.org 00:00:03.13] Searching Docker registry credential in CredsStore
2024-07-08T13:50:27.7722812Z [testcontainers.org 00:00:03.13] Docker registry credential mcr.microsoft.com not found
2024-07-08T13:51:06.0218757Z [testcontainers.org 00:00:41.38] Docker image mcr.microsoft.com/cosmosdb/linux/azure-cosmos-emulator:latest created
2024-07-08T13:51:06.0434532Z [testcontainers.org 00:00:41.40] Docker container 0ff41da9c645 created
2024-07-08T13:51:06.0463657Z [testcontainers.org 00:00:41.41] Start Docker container 0ff41da9c645
2024-07-08T13:51:06.3693777Z [testcontainers.org 00:00:41.73] Wait for Docker container 0ff41da9c645 to complete readiness checks
2024-07-08T13:51:31.9831721Z [testcontainers.org 00:01:07.35] Docker container 0ff41da9c645 ready
2024-07-08T13:51:32.9248338Z [2024-07-08 13:51:32.880] [WRN] - No XML encryptor configured. Key {cb7bdc46-d99f-48b1-ae44-49544d0189b7} may be persisted to storage in unencrypted form.
2024-07-08T13:51:32.9929913Z [2024-07-08 13:51:32.989] [INF] - Initialized Scheduler Signaller of type: Quartz.Core.SchedulerSignalerImpl
2024-07-08T13:51:32.9930939Z [2024-07-08 13:51:32.990] [INF] - Quartz Scheduler created
2024-07-08T13:51:32.9931861Z [2024-07-08 13:51:32.990] [INF] - JobFactory set to: Quartz.Simpl.MicrosoftDependencyInjectionJobFactory
2024-07-08T13:51:32.9932721Z [2024-07-08 13:51:32.990] [INF] - RAMJobStore initialized.
2024-07-08T13:51:32.9933498Z [2024-07-08 13:51:32.991] [INF] - Quartz Scheduler 3.8.1.0 - 'QuartzScheduler' with instanceId 'NON_CLUSTERED' initialized
2024-07-08T13:51:33.0093126Z [2024-07-08 13:51:32.991] [INF] - Using thread pool 'Quartz.Simpl.DefaultThreadPool', size: 10
2024-07-08T13:51:33.0093831Z [2024-07-08 13:51:32.991] [INF] - Using job store 'Quartz.Simpl.RAMJobStore', supports persistence: False, clustered: False
2024-07-08T13:51:33.0094307Z [2024-07-08 13:51:33.007] [INF] - Adding 2 jobs, 2 triggers.
2024-07-08T13:51:33.0106762Z [2024-07-08 13:51:33.010] [INF] - Adding job: DEFAULT.CommandDelegateJob
2024-07-08T13:51:33.0337185Z [2024-07-08 13:51:33.032] [INF] - Adding job: DEFAULT.NewScheduledJob
2024-07-08T13:51:33.9687071Z [2024-07-08 13:51:33.964] [WRN] - Failed to determine the https port for redirect.
2024-07-08T13:51:34.2813210Z [2024-07-08 13:51:34.280] [INF] - Scheduler QuartzScheduler_$_NON_CLUSTERED started.
2024-07-08T13:51:38.6400875Z [2024-07-08 13:51:38.611] [ERR] - CleanArchitecture Request: Unhandled Exception for Request "UpdateEntityAfterEtagWasChangedByPreviousOperationTest" UpdateEntityAfterEtagWasChangedByPreviousOperationTest {}
2024-07-08T13:51:38.6408540Z Microsoft.Azure.Cosmos.CosmosException : Response status code does not indicate success: PreconditionFailed (412); Substatus: 0; ActivityId: 2e175277-50dd-4fc3-8a03-00cfb844d334; Reason: (
2024-07-08T13:51:38.6408958Z code : PreconditionFailed
2024-07-08T13:51:38.6411554Z message : Message: {"Errors":["One of the specified pre-condition is not met. Learn more: https:\/\/aka.ms\/CosmosDB\/sql\/errors\/precondition-failed"]}
2024-07-08T13:51:38.6413442Z ActivityId: 2e175277-50dd-4fc3-8a03-00cfb844d334, Request URI: /apps/DocDbApp/services/DocDbServer1/partitions/a4cb494d-38c8-11e6-8106-8cdcd42c33be/replicas/1p/, RequestStats:
2024-07-08T13:51:38.6414346Z RequestStartTime: 2024-07-08T13:51:38.5917398Z, RequestEndTime: 2024-07-08T13:51:38.5958371Z, Number of regions attempted:1
2024-07-08T13:51:38.6415460Z {"systemHistory":[{"dateUtc":"2024-07-08T13:51:33.4411179Z","cpu":100.000,"memory":3605024.000,"threadInfo":{"isThreadStarving":"no info","availableThreads":32765,"minThreads":2,"maxThreads":32767},"numberOfOpenTcpConnection":0}]}
2024-07-08T13:51:38.6426656Z RequestStart: 2024-07-08T13:51:38.5917398Z; ResponseTime: 2024-07-08T13:51:38.5958371Z; StoreResult: StorePhysicalAddress: rntbd://172.17.0.3:10253/apps/DocDbApp/services/DocDbServer1/partitions/a4cb494d-38c8-11e6-8106-8cdcd42c33be/replicas/1p/, LSN: 3, GlobalCommittedLsn: -1, PartitionKeyRangeId: 0, IsValid: True, StatusCode: 412, SubStatusCode: 0, RequestCharge: 1.24, ItemLSN: -1, SessionToken: -1#3, UsingLocalLSN: False, TransportException: null, BELatencyMs: 0.59, ActivityId: 2e175277-50dd-4fc3-8a03-00cfb844d334, RetryAfterInMs: , ReplicaHealthStatuses: [(port: 10253 | status: Connected | lkt: 07/08/2024 13:51:37)], TransportRequestTimeline: {"requestTimeline":[{"event": "Created", "startTimeUtc": "2024-07-08T13:51:38.5917398Z", "durationInMs": 0.1039},{"event": "ChannelAcquisitionStarted", "startTimeUtc": "2024-07-08T13:51:38.5918437Z", "durationInMs": 0.0027},{"event": "Pipelined", "startTimeUtc": "2024-07-08T13:51:38.5918464Z", "durationInMs": 0.3789},{"event": "Transit Time", "startTimeUtc": "2024-07-08T13:51:38.5922253Z", "durationInMs": 0.9483},{"event": "Received", "startTimeUtc": "2024-07-08T13:51:38.5931736Z", "durationInMs": 0.4703},{"event": "Completed", "startTimeUtc": "2024-07-08T13:51:38.5936439Z", "durationInMs": 0}],"serviceEndpointStats":{"inflightRequests":1,"openConnections":1},"connectionStats":{"waitforConnectionInit":"False","callsPendingReceive":0,"lastSendAttempt":"2024-07-08T13:51:38.5709247Z","lastSend":"2024-07-08T13:51:38.5709247Z","lastReceive":"2024-07-08T13:51:38.5832758Z"},"requestSizeInBytes":864,"requestBodySizeInBytes":264,"responseMetadataSizeInBytes":182,"responseBodySizeInBytes":134};
2024-07-08T13:51:38.6429443Z ResourceType: Document, OperationType: Upsert
2024-07-08T13:51:38.6429667Z , SDK: Microsoft.Azure.Documents.Common/2.14.0
2024-07-08T13:51:38.6429854Z );
2024-07-08T13:51:38.6430436Z at Microsoft.Azure.Cosmos.ResponseMessage.EnsureSuccessStatusCode()
2024-07-08T13:51:38.6430759Z at Microsoft.Azure.Cosmos.CosmosResponseFactoryCore.ProcessMessage[T](ResponseMessage responseMessage, Func`2 createResponse)
2024-07-08T13:51:38.6431085Z at Microsoft.Azure.Cosmos.CosmosResponseFactoryCore.CreateItemResponse[T](ResponseMessage responseMessage)
2024-07-08T13:51:38.6431483Z at Microsoft.Azure.Cosmos.ContainerCore.UpsertItemAsync[T](T item, ITrace trace, Nullable`1 partitionKey, ItemRequestOptions requestOptions, CancellationToken cancellationToken)
2024-07-08T13:51:38.6432139Z at Microsoft.Azure.Cosmos.ClientContextCore.RunWithDiagnosticsHelperAsync[TResult](String containerName, String databaseName, OperationType operationType, ITrace trace, Func`2 task, Func`2 openTelemetry, String operationName, RequestOptions requestOptions)
2024-07-08T13:51:38.6432789Z at Microsoft.Azure.Cosmos.ClientContextCore.OperationHelperWithRootTraceAsync[TResult](String operationName, String containerName, String databaseName, OperationType operationType, RequestOptions requestOptions, Func`2 task, Func`2 openTelemetry, TraceComponent traceComponent, TraceLevel traceLevel)
2024-07-08T13:51:38.6433329Z at Microsoft.Azure.CosmosRepository.DefaultRepository`1.UpdateAsync(TItem value, Boolean ignoreEtag, CancellationToken cancellationToken)
2024-07-08T13:51:38.6474424Z at AdvancedMappingCrud.Cosmos.Tests.Infrastructure.Repositories.CosmosDBRepositoryBase`3.<>c__DisplayClass8_0.<
@niteshvijay1995 I'm looking in to how to grab the emulator logs for you. In my local testing I'm seeing nothing of interest in there. For a full run where all the tests are passing, it's literally just giving me:
2024-07-09T14:48:25.077797514Z This is an evaluation version. There are [96] days left in the evaluation period.
2024-07-09T14:48:29.014322440Z Starting
2024-07-09T14:48:52.741548345Z Starting 1/11 partitions
...
2024-07-09T14:49:16.981054047Z Started 11/11 partitions
2024-07-09T14:49:16.981083958Z Started
Is there some kind of flag or environment variable I should be setting to tell the emulator to output more verbose logs?
@kntajus i think the logs should be accessible via a docker logs
cli command - if i remember correctly the service containers in a devops pipeline run in the docker instance bootstrapped for that pipeline run
Thanks @razvangoga, given that I'm using Testcontainers I've found a way to access the container logs directly from the test code anyway.
@JonathanLydall I don't know if this might be useful for you too, looks like you're using .NET - you can call GetLogsAsync on the instance representing the docker container that Testcontainers provides for you at the end of the test/run.
@kntajus cool!
genuinely curious if anything comes from them
the issue is hardware related and the behaviour is in line with how AzDevops assign agent VMs: based on the region of the AzDevops tenant you will get agents VMs in the same Azure region or in a fallback one ( docs )
it explains why some people (like me based in Germany where agents come from Germany or France azure regions) get only fails, while some others have more success (different azure zone => different hardware).
i mean we can also wait a couple of years more until MS upgrades all it's datacenteres from these pesky Intel(R) Xeon(R) Platinum 8272CL CPU @ 2.60GHz 😁
in any case i'll drink a beer each day @niteshvijay1995 doesn't ghost the repo like @sajeetharan did the last time around
I find it quite amusing that this issue has a Feature label. The emulator is supposed to work on Linux. There's nothing about only certain Linux agents in ADO. This is a bug not a feature.
Related to: https://github.com/actions/virtual-environments/issues/5036#issuecomment-1044270895
The Cosmos DB Linux Emulator fails to start on some Intel chips.
lscpu output: Architecture: x86_64 CPU op-mode(s): 32-bit, 64-bit
Byte Order: Little Endian Address sizes: [46] CPU(s): 2 On-line CPU(s) list: 0,1 Thread(s) per core: 1 Core(s) per socket: 2 Socket(s): 1 NUMA node(s): 1 Vendor ID: GenuineIntel CPU family: 6 Model: 85 Model name: Intel(R) Xeon(R) Platinum 8272CL CPU @ 2.60GHz Stepping: 7 CPU MHz: 2593.907 BogoMIPS: 87.81 Hypervisor vendor: Microsoft Virtualization type: full L1d cache: 64KiB L1i cache: 64 KiB L2 cache: 2 MiB L3 cache: 35.8 MiB NUMA node0 CPU(s): 0,1 Vulnerability Itlb multihit: KVM: Mitigation: VMX unsupported Vulnerability L1tf: Mitigation; PTE Inversion Vulnerability Mds: Mitigation; Clear CPU buffers; SMT Host state unknown Vulnerability Meltdown: Mitigation; PTI Vulnerability Spec store bypass: Vulnerable Vulnerability Spectre v1: Mitigation; usercopy/swapgs barriers and __user pointer sanitization Vulnerability Spectre v2: Mitigation; Full generic retpoline, STIBP disabled, RSB filling Vulnerability Srbds: Not affected Vulnerability Tsx async abort: Mitigation; Clear CPU buffers; SMT Host state unknown Flags: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ss ht syscall nx pdpe1gb rdtscp lm constant_tsc rep_good nopl xtopology cpuid pni pclmulqdq ssse3 fma cx16 pcid sse4_1 sse4_2 movbe popcnt aes xsave avx f16c rdrand hypervisor lahf_lm abm 3dnowprefetch invpcid_single pti fsgsbase bmi1 hle avx2 smep bmi2 erms invpcid rtm mpx avx512f avx512dq rdseed adx smap clflushopt avx512cd avx512bw avx512vl xsaveopt xsavec xsaves md_clear /proc/cpuinfo content: /proc/cpuinfo