Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-48425

Driver MONGODB-AWS auth ECS tests failing with TypeError: TestData is undefined

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Fixed
    • Priority: Icon: Major - P3 Major - P3
    • 4.7.0
    • Affects Version/s: None
    • Component/s: None
    • None
    • Fully Compatible
    • ALL
    • Security 2020-06-15
    • 50

      Driver MONGODB-AWS auth ECS tests are failing on Ubuntu:
      https://evergreen.mongodb.com/task/mongo_python_driver_aws_auth_test__platform~ubuntu_18.04_python_version~system_python_aws_auth_test_0eace78cf483ceecaf308cf7bdcec50e8e50ed7e_20_05_19_18_20_23

      ...
 [2020/05/26 18:58:30.491] sh21059| DEBUG:botocore.hooks:Event needs-retry.ecs.DescribeServices: calling handler <botocore.retryhandler.RetryHandler object at 0x7fa0eb12c518>
 [2020/05/26 18:58:30.491] sh21059| DEBUG:botocore.retryhandler:No retry needed.
 [2020/05/26 18:58:30.491] sh21059| DEBUG:botocore.waiter:Waiting complete, waiter matched the success state.
 [2020/05/26 18:58:30.493] sh21059| Traceback (most recent call last):
 [2020/05/26 18:58:30.493] sh21059|   File "lib/container_tester.py", line 385, in <module>
 [2020/05/26 18:58:30.493] sh21059|     main()
 [2020/05/26 18:58:30.493] sh21059|   File "lib/container_tester.py", line 381, in main
 [2020/05/26 18:58:30.493] sh21059|     args.func(args)
 [2020/05/26 18:58:30.493] sh21059|   File "lib/container_tester.py", line 291, in _run_e2e_test_args
 [2020/05/26 18:58:30.494] sh21059|     _run_e2e_test(args.script, args.files, args.cluster, args.task_definition, args.subnets, args.security_group)
 [2020/05/26 18:58:30.494] sh21059|   File "lib/container_tester.py", line 312, in _run_e2e_test
 [2020/05/26 18:58:30.494] sh21059|     run_test(endpoint, script, files)
 [2020/05/26 18:58:30.494] sh21059|   File "lib/container_tester.py", line 96, in run_test
 [2020/05/26 18:58:30.494] sh21059|     raise ValueError(f"test failed with {return_code}")
 [2020/05/26 18:58:30.494] sh21059| ValueError: test failed with 253
 [2020/05/26 18:58:30.533] uncaught exception: Error: [1] != [0] are not equal : Container Test failed :
 [2020/05/26 18:58:30.533] doassert@src/mongo/shell/assert.js:20:14
 [2020/05/26 18:58:30.533] assert.eq@src/mongo/shell/assert.js:179:9
 [2020/05/26 18:58:30.533] @aws_e2e_ecs.js:43:4
 [2020/05/26 18:58:30.533] @aws_e2e_ecs.js:6:2
 [2020/05/26 18:58:30.538] failed to load: aws_e2e_ecs.js
 [2020/05/26 18:58:30.538] exiting with code -3
 [2020/05/26 18:58:30.538] Command failed: command encountered problem: error waiting on process 'c360e6f8-c41e-4f4e-9180-c7dba9de3f80': exit status 253
 [2020/05/26 18:58:30.538] Task completed - FAILURE.

      The root cause might be the "TypeError: TestData is undefined" error from earlier in the same task:

       [2020/05/26 18:57:14.961] sh21059| d20000| {"t":{"$date":"2020-05-26T18:57:14.960+00:00"},"s":"I",  "c":"ACCESS",   "id":20250,   "ctx":"conn1","msg":"Successful authentication","attr":{"mechanism":"MONGODB-AWS","principalName":"arn:aws:sts::557821124784:assumed-role/ecsTaskExecutionRole/*","authenticationDatabase":"$external","client":"127.0.0.1:58852"}}
 [2020/05/26 18:57:14.962] sh21059| uncaught exception: TypeError: TestData is undefined :
 [2020/05/26 18:57:14.962] sh21059| MongoRunner.stopMongod@src/mongo/shell/servers.js:999:9
 [2020/05/26 18:57:14.962] sh21059| @ecs_hosted_test.js:36:1
 [2020/05/26 18:57:14.962] sh21059| @ecs_hosted_test.js:5:2
 [2020/05/26 18:57:14.962] sh21059| failed to load: ecs_hosted_test.js
 [2020/05/26 18:57:14.962] sh21059| exiting with code -3
 [2020/05/26 18:57:14.962] sh21059| {"t":{"$date":"2020-05-26T18:57:14.961Z"},"s":"I",  "c":"-",        "id":22819,   "ctx":"main","msg":"waiting for process {pid} to terminate.","attr":{"pid":"109"}}
 [2020/05/26 18:57:14.962] sh21059| d20000| {"t":{"$date":"2020-05-26T18:57:14.961+00:00"},"s":"I",  "c":"CONTROL",  "id":23377,   "ctx":"SignalHandler","msg":"got signal {sig} ({strsignal_sig})","attr":{"sig":15,"strsignal_sig":"Terminated"}}
 [2020/05/26 18:57:14.962] sh21059| d20000| {"t":{"$date":"2020-05-26T18:57:14.961+00:00"},"s":"I",  "c":"CONTROL",  "id":23378,   "ctx":"SignalHandler","msg":"kill from pid:{si_si_pid} uid:{si_si_uid}","attr":{"si_si_pid":104,"si_si_uid":0}}
 [2020/05/26 18:57:14.962] sh21059| d20000| {"t":{"$date":"2020-05-26T18:57:14.961+00:00"},"s":"I",  "c":"CONTROL",  "id":23381,   "ctx":"SignalHandler","msg":"will terminate after current cmd ends"}
 [2020/05/26 18:57:14.962] sh21059| d20000| {"t":{"$date":"2020-05-26T18:57:14.961+00:00"},"s":"I",  "c":"NETWORK",  "id":20562,   "ctx":"SignalHandler","msg":"Shutdown: going to close listening sockets"}
 [2020/05/26 18:57:14.962] sh21059| d20000| {"t":{"$date":"2020-05-26T18:57:14.961+00:00"},"s":"I",  "c":"NETWORK",  "id":23017,   "ctx":"listener","msg":"removing socket file: {path}","attr":{"path":"/tmp/mongodb-20000.sock"}}
 [2020/05/26 18:57:14.962] sh21059| d20000| {"t":{"$date":"2020-05-26T18:57:14.961+00:00"},"s":"I",  "c":"-",        "id":20520,   "ctx":"SignalHandler","msg":"Stopping further Flow Control ticket acquisitions."}
 [2020/05/26 18:57:14.962] sh21059| d20000| {"t":{"$date":"2020-05-26T18:57:14.961+00:00"},"s":"I",  "c":"-",        "id":4695300, "ctx":"SignalHandler","msg":"Interrupted all currently running operations","attr":{"opsKilled":3}}
 [2020/05/26 18:57:14.963] sh21059| d20000| {"t":{"$date":"2020-05-26T18:57:14.961+00:00"},"s":"I",  "c":"FTDC",     "id":20626,   "ctx":"SignalHandler","msg":"Shutting down full-time diagnostic data capture"}
 [2020/05/26 18:57:14.966] sh21059| d20000| {"t":{"$date":"2020-05-26T18:57:14.965+00:00"},"s":"I",  "c":"INDEX",    "id":36841000,"ctx":"SignalHandler","msg":"Shutting down TTL collection monitor thread"}
 [2020/05/26 18:57:14.966] sh21059| d20000| {"t":{"$date":"2020-05-26T18:57:14.965+00:00"},"s":"I",  "c":"INDEX",    "id":36841001,"ctx":"SignalHandler","msg":"Finished shutting down TTL collection monitor thread"}
 [2020/05/26 18:57:14.966] sh21059| d20000| {"t":{"$date":"2020-05-26T18:57:14.965+00:00"},"s":"I",  "c":"STORAGE",  "id":22320,   "ctx":"SignalHandler","msg":"Shutting down journal flusher thread"}
 [2020/05/26 18:57:14.966] sh21059| d20000| {"t":{"$date":"2020-05-26T18:57:14.965+00:00"},"s":"I",  "c":"STORAGE",  "id":22321,   "ctx":"SignalHandler","msg":"Finished shutting down journal flusher thread"}
 [2020/05/26 18:57:14.967] sh21059| d20000| {"t":{"$date":"2020-05-26T18:57:14.965+00:00"},"s":"I",  "c":"STORAGE",  "id":20282,   "ctx":"SignalHandler","msg":"Deregistering all the collections"}
 [2020/05/26 18:57:14.967] sh21059| d20000| {"t":{"$date":"2020-05-26T18:57:14.965+00:00"},"s":"I",  "c":"STORAGE",  "id":22261,   "ctx":"SignalHandler","msg":"Timestamp monitor shutting down"}
 [2020/05/26 18:57:14.967] sh21059| d20000| {"t":{"$date":"2020-05-26T18:57:14.965+00:00"},"s":"I",  "c":"STORAGE",  "id":22317,   "ctx":"SignalHandler","msg":"WiredTigerKVEngine shutting down"}
 [2020/05/26 18:57:14.967] sh21059| d20000| {"t":{"$date":"2020-05-26T18:57:14.966+00:00"},"s":"I",  "c":"STORAGE",  "id":22318,   "ctx":"SignalHandler","msg":"Shutting down session sweeper thread"}
 [2020/05/26 18:57:14.968] sh21059| d20000| {"t":{"$date":"2020-05-26T18:57:14.966+00:00"},"s":"I",  "c":"STORAGE",  "id":22319,   "ctx":"SignalHandler","msg":"Finished shutting down session sweeper thread"}
 [2020/05/26 18:57:14.968] sh21059| d20000| {"t":{"$date":"2020-05-26T18:57:14.966+00:00"},"s":"I",  "c":"STORAGE",  "id":22322,   "ctx":"SignalHandler","msg":"Shutting down checkpoint thread"}
 [2020/05/26 18:57:14.968] sh21059| d20000| {"t":{"$date":"2020-05-26T18:57:14.966+00:00"},"s":"I",  "c":"STORAGE",  "id":22323,   "ctx":"SignalHandler","msg":"Finished shutting down checkpoint thread"}
 [2020/05/26 18:57:14.968] sh21059| d20000| {"t":{"$date":"2020-05-26T18:57:14.966+00:00"},"s":"I",  "c":"STORAGE",  "id":47959002,"ctx":"SignalHandler","msg":"Closing WiredTiger","attr":{"closeConfig":"leak_memory=true,"}}
 [2020/05/26 18:57:15.052] sh21059| d20000| {"t":{"$date":"2020-05-26T18:57:15.050+00:00"},"s":"I",  "c":"STORAGE",  "id":47959001,"ctx":"SignalHandler","msg":"WiredTiger closed","attr":{"durationMillis":84}}
 [2020/05/26 18:57:15.052] sh21059| d20000| {"t":{"$date":"2020-05-26T18:57:15.050+00:00"},"s":"I",  "c":"STORAGE",  "id":22279,   "ctx":"SignalHandler","msg":"shutdown: removing fs lock..."}
 [2020/05/26 18:57:15.052] sh21059| d20000| {"t":{"$date":"2020-05-26T18:57:15.050+00:00"},"s":"I",  "c":"CONTROL",  "id":20565,   "ctx":"SignalHandler","msg":"Now exiting"}
 [2020/05/26 18:57:15.054] sh21059| d20000| {"t":{"$date":"2020-05-26T18:57:15.051+00:00"},"s":"I",  "c":"CONTROL",  "id":23138,   "ctx":"SignalHandler","msg":"Shutting down","attr":{"exitCode":0}}
 [2020/05/26 18:57:15.055] sh21059| {"t":{"$date":"2020-05-26T18:57:15.054Z"},"s":"I",  "c":"QUERY",    "id":22787,   "ctx":"js","msg":"MozJS GC {status_JSGC_BEGIN_prologue_epilogue} heap stats -  total: {mongo_sm_get_total_bytes} limit: {mongo_sm_get_max_bytes}","attr":{"status_JSGC_BEGIN_prologue_epilogue":"prologue","mongo_sm_get_total_bytes":4611559,"mongo_sm_get_max_bytes":0}}
 [2020/05/26 18:57:15.057] sh21059| {"t":{"$date":"2020-05-26T18:57:15.055Z"},"s":"I",  "c":"NETWORK",  "id":20125,   "ctx":"js","msg":"DBClientConnection failed to receive message","attr":{"connString":"127.0.0.1:20000","error":"HostUnreachable: Connection closed by peer"}}
 [2020/05/26 18:57:15.057] sh21059| {"t":{"$date":"2020-05-26T18:57:15.056Z"},"s":"D1", "c":"-",        "id":23074,   "ctx":"js","msg":"User assertion","attr":{"error":"HostUnreachable: network error while attempting to run command 'endSessions' on host '127.0.0.1:20000' ","file":"src/mongo/client/dbclient_base.cpp","line":225}}
 [2020/05/26 18:57:15.057] sh21059| {"t":{"$date":"2020-05-26T18:57:15.056Z"},"s":"I",  "c":"QUERY",    "id":22791,   "ctx":"js","msg":"Failed to end session {lsid} due to {status}","attr":{"lsid":{"id":{"$uuid":"6bbbabba-c84a-4c57-a8a3-67be291e794e"}},"status":{"code":6,"codeName":"HostUnreachable","errmsg":"network error while attempting to run command 'endSessions' on host '127.0.0.1:20000' "}}}
 [2020/05/26 18:57:15.058] sh21059| {"t":{"$date":"2020-05-26T18:57:15.057Z"},"s":"I",  "c":"QUERY",    "id":22787,   "ctx":"js","msg":"MozJS GC {status_JSGC_BEGIN_prologue_epilogue} heap stats -  total: {mongo_sm_get_total_bytes} limit: {mongo_sm_get_max_bytes}","attr":{"status_JSGC_BEGIN_prologue_epilogue":"epilogue","mongo_sm_get_total_bytes":607,"mongo_sm_get_max_bytes":0}}
 [2020/05/26 18:57:15.060] sh21059| + RET_CODE=253
 [2020/05/26 18:57:15.060] sh21059| RETURN CODE: 253
 [2020/05/26 18:57:15.060] sh21059| + echo RETURN CODE: 253
 [2020/05/26 18:57:15.060] sh21059| + exit 253
 [2020/05/26 18:57:15.062] sh21059| INFO:__main__:RETURN CODE: 253
 [2020/05/26 18:57:15.062] sh21059| ERROR:__main__:FAILED: 253

      The last time this test passed was:

       [2020/05/22 00:11:11.869] db version v4.5.0-1381-g8a92b05

      And now the test is failing consistently:

       [2020/05/26 18:54:21.975] db version v4.5.0-1412-g5648a67

      So the issue is likely somewhere between v4.5.0-1381 and v4.5.0-1412.

            Assignee:
            mark.benvenuto@mongodb.com Mark Benvenuto
            Reporter:
            shane.harvey@mongodb.com Shane Harvey
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

              Created:
              Updated:
              Resolved: