Back to build
Raw log | Switch to full mode | Login

Set PYTHONPATH: /b/swarming/w/ir/kitchen-checkout/build/scripts:/b/swarming/w/ir/kitchen-checkout/build/site_config:/b/swarming/w/ir/kitchen-checkout/build/third_party:/b/swarming/w/ir/kitchen-checkout/build/third_party/buildbot_8_4p1:/b/swarming/w/ir/kitchen-checkout/build/third_party/buildbot_slave_8_4:/b/swarming/w/ir/kitchen-checkout/build/third_party/coverage-3.7.1:/b/swarming/w/ir/kitchen-checkout/build/third_party/decorator_3_3_1:/b/swarming/w/ir/kitchen-checkout/build/third_party/google_api_python_client:/b/swarming/w/ir/kitchen-checkout/build/third_party/httplib2/python2:/b/swarming/w/ir/kitchen-checkout/build/third_party/infra_libs:/b/swarming/w/ir/kitchen-checkout/build/third_party/jinja2:/b/swarming/w/ir/kitchen-checkout/build/third_party/markupsafe:/b/swarming/w/ir/kitchen-checkout/build/third_party/oauth2client:/b/swarming/w/ir/kitchen-checkout/build/third_party/pyasn1:/b/swarming/w/ir/kitchen-checkout/build/third_party/pyasn1-modules:/b/swarming/w/ir/kitchen-checkout/build/third_party/python-rsa:/b/swarming/w/ir/kitchen-checkout/build/third_party/requests_2_10_0:/b/swarming/w/ir/kitchen-checkout/build/third_party/setuptools-0.6c11:/b/swarming/w/ir/kitchen-checkout/build/third_party/sqlalchemy_0_7_1:/b/swarming/w/ir/kitchen-checkout/build/third_party/sqlalchemy_migrate_0_7_1:/b/swarming/w/ir/kitchen-checkout/build/third_party/tempita_0_5:/b/swarming/w/ir/kitchen-checkout/build/third_party/twisted_10_2:/b/swarming/w/ir/kitchen-checkout/build/third_party/uritemplate:/b/swarming/w/ir/kitchen-checkout/build/third_party/site-packages 2019-05-25 07:40:24,205 - root: [DEBUG] Using task_output_dir: '/b/swarming/w/ir/tmp/t/tmpYufjOA' 2019-05-25 07:40:24,205 - root: [WARNING] task_output_dir '/b/swarming/w/ir/tmp/t/tmpYufjOA' already exists! 2019-05-25 07:40:24,205 - root: [WARNING] task_output_dir existing content: [] 2019-05-25 07:40:24,205 - root: [INFO] collect_cmd: swarming collect -server https://chromium-swarm.appspot.com -worker 50 -task-summary-python -task-output-stdout all -verbose -requests-json /b/swarming/w/ir/tmp/t/tmplBuKjQ.json -output-dir /b/swarming/w/ir/tmp/t/tmpYufjOA -task-summary-json /b/swarming/w/ir/tmp/t/tmpMFCle2.json [D2019-05-25T07:40:24.217459Z 7883 0 auth.go:1265] Minting a new token {"key":"luci_ctx/c0aca0b3eae626047fd4a2df7ebed40a16c4455cecce248f541fc9210d2d3f3f", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-05-25T07:40:24.217564Z 7883 0 luci_ctx.go:138] POST http://127.0.0.1:33461/rpc/LuciLocalAuthService.GetOAuthToken {"key":"luci_ctx/c0aca0b3eae626047fd4a2df7ebed40a16c4455cecce248f541fc9210d2d3f3f", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-05-25T07:40:24.220854Z 7883 0 auth.go:1222] Token expires in 49m10.779194744s {"key":"luci_ctx/c0aca0b3eae626047fd4a2df7ebed40a16c4455cecce248f541fc9210d2d3f3f", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-05-25T07:40:25.686094Z 7883 0 collect.go:311] Waiting task_id: 4506bfe548c1a410 [D2019-05-25T07:40:27.135592Z 7883 0 collect.go:311] Waiting task_id: 4506bfe548c1a410 [D2019-05-25T07:40:28.488527Z 7883 0 collect.go:311] Waiting task_id: 4506bfe548c1a410 [D2019-05-25T07:40:30.114480Z 7883 0 collect.go:311] Waiting task_id: 4506bfe548c1a410 [D2019-05-25T07:40:32.083075Z 7883 0 collect.go:311] Waiting task_id: 4506bfe548c1a410 [D2019-05-25T07:40:33.962585Z 7883 0 collect.go:311] Waiting task_id: 4506bfe548c1a410 [D2019-05-25T07:40:35.749479Z 7883 0 collect.go:311] Waiting task_id: 4506bfe548c1a410 [D2019-05-25T07:40:37.339139Z 7883 0 collect.go:311] Waiting task_id: 4506bfe548c1a410 [D2019-05-25T07:40:39.020987Z 7883 0 collect.go:311] Waiting task_id: 4506bfe548c1a410 [D2019-05-25T07:40:40.707964Z 7883 0 collect.go:311] Waiting task_id: 4506bfe548c1a410 [D2019-05-25T07:40:42.633207Z 7883 0 collect.go:311] Waiting task_id: 4506bfe548c1a410 [D2019-05-25T07:40:44.454833Z 7883 0 collect.go:311] Waiting task_id: 4506bfe548c1a410 [D2019-05-25T07:40:46.385941Z 7883 0 collect.go:311] Waiting task_id: 4506bfe548c1a410 [D2019-05-25T07:40:48.301715Z 7883 0 collect.go:311] Waiting task_id: 4506bfe548c1a410 [D2019-05-25T07:40:50.428717Z 7883 0 collect.go:311] Waiting task_id: 4506bfe548c1a410 [D2019-05-25T07:40:52.534108Z 7883 0 collect.go:311] Waiting task_id: 4506bfe548c1a410 [D2019-05-25T07:40:54.659012Z 7883 0 collect.go:311] Waiting task_id: 4506bfe548c1a410 4506bfe548c1a410: exit 0 INFO:root:Running ['/b/s/w/ir/tools_webrtc/audio_quality/linux/PolqaOem64', '-q', '-LC', 'NB', '-Ref', '/b/s/w/ir/resources/voice_engine/audio_tiny48.wav', '-Test', '/b/s/w/ir/resources/voice_engine/audio_tiny48.wav'] INFO:root:Running ['./low_bandwidth_audio_test', '--sample_rate_hz=16000'] [==========] Running 2 tests from 1 test suite. [----------] Global test environment set-up. [----------] 2 tests from LowBandwidthAudioTest [ RUN ] LowBandwidthAudioTest.GoodNetworkHighBitrate (audio_processing_impl.cc:435): Capture analyzer activated: 0 Capture post processor activated: 0 Render pre processor activated: 0 (audio_processing_impl.cc:435): Capture analyzer activated: 0 Capture post processor activated: 0 Render pre processor activated: 0 (bitrate_prober.cc:66): Bandwidth probing enabled, set to inactive (paced_sender.cc:421): ProcessThreadAttached 0xc80a9940 (cpu_info.cc:53): Available number of cores: 8 (aimd_rate_control.cc:105): Using aimd rate control with back off factor 0.85 (remote_bitrate_estimator_single_stream.cc:71): RemoteBitrateEstimatorSingleStream: Instantiating. (remote_estimator_proxy.cc:44): Maximum interval between transport feedback RTCP messages (ms): 250 (bitrate_prober.cc:66): Bandwidth probing enabled, set to inactive (paced_sender.cc:421): ProcessThreadAttached 0xc80b22f0 (aimd_rate_control.cc:105): Using aimd rate control with back off factor 0.85 (remote_bitrate_estimator_single_stream.cc:71): RemoteBitrateEstimatorSingleStream: Instantiating. (remote_estimator_proxy.cc:44): Maximum interval between transport feedback RTCP messages (ms): 250 (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=down (rtp_transport_controller_send.cc:268): SignalNetworkState Down (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=down (rtp_transport_controller_send.cc:268): SignalNetworkState Down (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=down (rtp_transport_controller_send.cc:268): SignalNetworkState Down (neteq_impl.cc:123): NetEq config: sample_rate_hz=16000, enable_post_decode_vad=true, max_packets_in_buffer=200, min_delay_ms=0, enable_fast_accelerate=false, enable_muted_state=false, enable_rtx_handling=false (audio_coding_module.cc:311): Created (audio_send_stream.cc:142): AudioSendStream: 3735928559 (audio_send_stream.cc:230): AudioSendStream::ConfigureStream: {rtp: {ssrc: 3735928559, extmap-allow-mixed: false, extensions: [], c_name: }, rtcp_report_interval_ms: 5000, send_transport: (Transport), media_transport_config: {media_transport: null}, min_bitrate_bps: -1, max_bitrate_bps: -1, send_codec_spec: {nack_enabled: false, transport_cc_enabled: false, cng_payload_type: <unset>, payload_type: 103, format: {name: opus, clockrate_hz: 48000, num_channels: 2, parameters: {stereo: 1}}}} (audio_encoder_opus.cc:767): Set Opus bitrate to 64000 bps. (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=up (rtp_transport_controller_send.cc:268): SignalNetworkState Up (rtp_transport_controller_send.cc:462): Creating fallback congestion controller (neteq_impl.cc:123): NetEq config: sample_rate_hz=16000, enable_post_decode_vad=true, max_packets_in_buffer=200, min_delay_ms=0, enable_fast_accelerate=false, enable_muted_state=true, enable_rtx_handling=false (audio_coding_module.cc:311): Created (audio_receive_stream.cc:117): AudioReceiveStream: 3735928559 (audio_receive_stream.cc:361): AudioReceiveStream::ConfigureStream: {rtp: {remote_ssrc: 3735928559, local_ssrc: 19088743, transport_cc: off, nack: {rtp_history_ms: 0}, extensions: []}, rtcp_send_transport: (Transport), media_transport_config: {media_transport: null}} (alr_experiment.cc:78): Using ALR experiment settings: pacing factor: 1, max pacer queue length: 2875, ALR start bandwidth usage percent: 80, ALR end budget level percent: 40, ALR end budget level percent: -60, ALR experiment group ID: 3 (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=up (rtp_transport_controller_send.cc:268): SignalNetworkState Up (trendline_estimator.cc:121): Using Trendline filter for delay change estimation with window size 20 (aimd_rate_control.cc:105): Using aimd rate control with back off factor 0.85 (delay_based_bwe.cc:267): BWE Setting start bitrate to: 300 kbps (rtp_transport_controller_send.cc:462): Creating fallback congestion controller (probe_controller.cc:266): Measured bitrate: 300000 Minimum to probINFO:root:Running ['/b/s/w/ir/tools_webrtc/audio_quality/linux/pesq', '+16000', 'audio_tiny16.wav', 'LowBandwidth_GoodNetworkHighBitrate_16.wav'] e further: 1260000 (bitrate_prober.cc:114): Probe cluster (bitrate:min bytes:min packets): (900000:1687:5) (bitrate_prober.cc:114): Probe cluster (bitrate:min bytes:min packets): (1800000:3375:5) (bitrate_allocator.cc:117): Current BWE 300000 (alr_experiment.cc:78): Using ALR experiment settings: pacing factor: 1, max pacer queue length: 2875, ALR start bandwidth usage percent: 80, ALR end budget level percent: 40, ALR end budget level percent: -60, ALR experiment group ID: 3 (trendline_estimator.cc:121): Using Trendline filter for delay change estimation with window size 20 (aimd_rate_control.cc:105): Using aimd rate control with back off factor 0.85 (delay_based_bwe.cc:267): BWE Setting start bitrate to: 300 kbps (probe_controller.cc:266): Measured bitrate: 300000 Minimum to probe further: 1260000 (bitrate_prober.cc:114): Probe cluster (bitrate:min bytes:min packets): (900000:1687:5) (bitrate_prober.cc:114): Probe cluster (bitrate:min bytes:min packets): (1800000:3375:5) (bitrate_allocator.cc:117): Current BWE 300000 (rtp_sender_audio.cc:260): First audio RTP packet sent to pacer (probe_controller.cc:364): kWaitingForProbingResult: timeout (probe_controller.cc:364): kWaitingForProbingResult: timeout (fake_network_pipe.cc:212): Network queue: 5 ms. (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=down (rtp_transport_controller_send.cc:268): SignalNetworkState Down (audio_send_stream.cc:179): ~AudioSendStream: 3735928559 (paced_sender.cc:106): PacedSender paused. (control_handler.cc:77): Bitrate estimate state changed, BWE: 300 kbps. (bitrate_allocator.cc:117): Current BWE 0 (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=down (rtp_transport_controller_send.cc:268): SignalNetworkState Down (audio_receive_stream.cc:140): ~AudioReceiveStream: 3735928559 (paced_sender.cc:106): PacedSender paused. (control_handler.cc:77): Bitrate estimate state changed, BWE: 300 kbps. (bitrate_allocator.cc:117): Current BWE 0 (paced_sender.cc:421): ProcessThreadAttached 0x0 (paced_sender.cc:421): ProcessThreadAttached 0x0 (paced_sender.cc:421): ProcessThreadAttached 0x0 (paced_sender.cc:421): ProcessThreadAttached 0x0 TEST GoodNetworkHighBitrate /b/s/w/ir/resources/voice_engine/audio_tiny16.wav /b/s/w/ir/out/LowBandwidth_GoodNetworkHighBitrate_16.wav RESULT pesq_mos: GoodNetworkHighBitrate= 3.049 score [ OK ] LowBandwidthAudioTest.GoodNetworkHighBitrate (5922 ms) [ RUN ] LowBandwidthAudioTest.Mobile2GNetwork (audio_processing_impl.cc:435): Capture analyzer activated: 0 Capture post processor activated: 0 Render pre processor activated: 0 (audio_processing_impl.cc:435): Capture analyzer activated: 0 Capture post processor activated: 0 Render pre processor activated: 0 (bitrate_prober.cc:66): Bandwidth probing enabled, set to inactive (paced_sender.cc:421): ProcessThreadAttached 0xc80ad6a0 (aimd_rate_control.cc:105): Using aimd rate control with back off factor 0.85 (remote_bitrate_estimator_single_stream.cc:71): RemoteBitrateEstimatorSingleStream: Instantiating. (remote_estimator_proxy.cc:44): Maximum interval between transport feedback RTCP messages (ms): 250 (bitrate_prober.cc:66): Bandwidth probing enabled, set to inactive (paced_sender.cc:421): ProcessThreadAttached 0xc80bcbb0 (aimd_rate_control.cc:105): Using aimd rate control with back off factor 0.85 (remote_bitrate_estimator_single_stream.cc:71): RemoteBitrateEstimatorSingleStream: Instantiating. (remote_estimator_proxy.cc:44): Maximum interval between transport feedback RTCP messages (ms): 250 (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=down (rtp_transport_controller_send.cc:268): SignalNetworkState Down (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=down (rtp_transport_controller_send.cc:268): SignalNetworkState Down (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=down (rtp_transport_controller_send.cc:268): SignalNetworkState Down (neteq_impl.cc:123): NetEq config: sample_rate_hz=16000, enable_post_decode_vad=true, max_packets_in_buffer=200, min_delay_ms=0, enable_fast_accelerate=false, enable_muted_state=false, enable_rtx_handling=false (audio_coding_module.cc:311): Created (audio_send_stream.cc:142): AudioSendStream: 3735928559 (audio_send_stream.cc:230): AudioSendStream::ConfigureStream: {rtp: {ssrc: 3735928559, extmap-allow-mixed: false, extensions: [], c_name: }, rtcp_report_interval_ms: 5000, send_transport: (Transport), media_transport_config: {media_transport: null}, min_bitrate_bps: -1, max_bitrate_bps: -1, send_codec_spec: {nack_enabled: false, transport_cc_enabled: false, cng_payload_type: <unset>, payload_type: 103, format: {name: OPUS, clockrate_hz: 48000, num_channels: 2, parameters: {maxaveragebitrate: 6000, ptime: 60, stereo: 1}}}} (audio_encoder_opus.cc:767): Set Opus bitrate to 6000 bps. (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=up (rtp_transport_controller_send.cc:268): SignalNetworkState Up (rtp_transport_controller_send.cc:462): Creating fallback congestion controller (neteq_impl.cc:123): NetEq config: sample_rate_hz=16000, enable_post_decode_vad=true, max_packets_in_buffer=200, min_delay_ms=0, enable_fast_accelerate=false, enable_muted_state=true, enable_rtx_handling=false (audio_coding_module.cc:311): Created (audio_receive_stream.cc:117): AudioReceiveStream: 3735928559 (audio_receive_stream.cc:361): AudioReceiveStream::ConfigureStream: {rtp: {remote_ssrc: 3735928559, local_ssrc: 19088743, transport_cc: off, nack: {rtp_history_ms: 0}, extensions: []}, rtcp_send_transport: (Transport), media_transport_config: {media_transport: null}} (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=up (alr_experiment.cc:78): Using ALR experiment settings: pacing factor: 1, max pacer queue length: 2875, ALR start bandwidth usage percent: 80, ALR end budget level percent: 40, ALR end budget level percent: -60, ALR experiment group ID: 3 (rtp_transport_controller_send.cc:268): SignalNetworkState Up (trendline_estimator.cc:121): Using Trendline filter for delay change estimation with window size 20 (aimd_rate_control.cc:105): Using aimd rate control with back off factor 0.85 (delay_based_bwe.cc:267): BWE Setting start bitrate to: 300 kbps (rtp_transport_controller_send.cc:462): Creating fallback congestion controller (probe_controller.cc:266): Measured bitrate: 300000 Minimum to probe further: 1260000 (bitrate_prober.cc:114): Probe cluster (bitrate:min bytes:min packets): (900000:1687:5) (bitrate_prober.cc:114): Probe cluster (bitrate:min bytes:min packets): (1800000:3375:5) (bitrate_allocator.cc:117): Current BWE 300000 (alr_experiment.cc:78): Using ALR experiment settings: pacing factor: 1, max pacer queue length: 2875, ALR start bandwidth usage percent: 80, ALR end budget level percent: 40, ALR end budget level percent: -60, ALR experiment group ID: 3 (trendline_estimator.cc:121): Using Trendline filter for delay change estimation with window size 20 (aimd_rate_control.cc:105): Using aimd rate control with back off factor 0.85 (delay_based_bwe.cc:267): BWE Setting start bitrate to: 300 kbps (probe_controller.cc:266): Measured bitrate: 300000 Minimum to probe further: 1260000 (bitrate_prober.cc:114): Probe cluster (bitrate:min bytes:min packets): (900000:1687:5) (bitrate_prober.cc:114): Probe cluster (bitrate:min bytes:min packets): (1800000:3375:5) (bitrate_allocator.cc:117): Current BWE 300000 (rtp_sender_audio.cc:260): First audio RTP packet sent to pacer (probe_controller.cc:364): kWaitingForProbingResult: timeout (probe_controller.cc:364): kWaitingForProbingResult: timeout (fake_network_pipe.cc:212): Network queue: 4 ms. (fake_network_pipe.cc:212): Network queue: 459 ms. (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=down (rtp_transport_controller_send.cc:268): SignalNetworkState Down (audio_send_stream.cc:179): ~AudioSendStream: 3735928559 (paced_sender.cc:106): PacedSender paused. (control_handler.cc:77): Bitrate estimate state changed, BWE: 300 kbps. (bitrate_allocator.cc:117): Current BWE 0 (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=down (rtp_transport_controller_send.cc:268): SignalNetworkState Down (audio_receive_stream.cc:140): ~AudioReceiveSINFO:root:Running ['/b/s/w/ir/tools_webrtc/audio_quality/linux/pesq', '+16000', 'audio_tiny16.wav', 'LowBandwidth_Mobile2GNetwork_16.wav'] INFO:root:Running ['./low_bandwidth_audio_test', '--sample_rate_hz=48000'] tream: 3735928559 (paced_sender.cc:106): PacedSender paused. (control_handler.cc:77): Bitrate estimate state changed, BWE: 300 kbps. (bitrate_allocator.cc:117): Current BWE 0 (paced_sender.cc:421): ProcessThreadAttached 0x0 (paced_sender.cc:421): ProcessThreadAttached 0x0 (paced_sender.cc:421): ProcessThreadAttached 0x0 (paced_sender.cc:421): ProcessThreadAttached 0x0 TEST Mobile2GNetwork /b/s/w/ir/resources/voice_engine/audio_tiny16.wav /b/s/w/ir/out/LowBandwidth_Mobile2GNetwork_16.wav RESULT pesq_mos: Mobile2GNetwork= 2.127 score [ OK ] LowBandwidthAudioTest.Mobile2GNetwork (6314 ms) [----------] 2 tests from LowBandwidthAudioTest (12236 ms total) [----------] Global test environment tear-down [==========] 2 tests from 1 test suite ran. (12236 ms total) [ PASSED ] 2 tests. [==========] Running 2 tests from 1 test suite. [----------] Global test environment set-up. [----------] 2 tests from LowBandwidthAudioTest [ RUN ] LowBandwidthAudioTest.GoodNetworkHighBitrate (audio_processing_impl.cc:435): Capture analyzer activated: 0 Capture post processor activated: 0 Render pre processor activated: 0 (audio_processing_impl.cc:435): Capture analyzer activated: 0 Capture post processor activated: 0 Render pre processor activated: 0 (bitrate_prober.cc:66): Bandwidth probing enabled, set to inactive (paced_sender.cc:421): ProcessThreadAttached 0x300a9e50 (cpu_info.cc:53): Available number of cores: 8 (aimd_rate_control.cc:105): Using aimd rate control with back off factor 0.85 (remote_bitrate_estimator_single_stream.cc:71): RemoteBitrateEstimatorSingleStream: Instantiating. (remote_estimator_proxy.cc:44): Maximum interval between transport feedback RTCP messages (ms): 250 (bitrate_prober.cc:66): Bandwidth probing enabled, set to inactive (paced_sender.cc:421): ProcessThreadAttached 0x300b2810 (aimd_rate_control.cc:105): Using aimd rate control with back off factor 0.85 (remote_bitrate_estimator_single_stream.cc:71): RemoteBitrateEstimatorSingleStream: Instantiating. (remote_estimator_proxy.cc:44): Maximum interval between transport feedback RTCP messages (ms): 250 (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=down (rtp_transport_controller_send.cc:268): SignalNetworkState Down (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=down (rtp_transport_controller_send.cc:268): SignalNetworkState Down (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=down (rtp_transport_controller_send.cc:268): SignalNetworkState Down (neteq_impl.cc:123): NetEq config: sample_rate_hz=16000, enable_post_decode_vad=true, max_packets_in_buffer=200, min_delay_ms=0, enable_fast_accelerate=false, enable_muted_state=false, enable_rtx_handling=false (audio_coding_module.cc:311): Created (audio_send_stream.cc:142): AudioSendStream: 3735928559 (audio_send_stream.cc:230): AudioSendStream::ConfigureStream: {rtp: {ssrc: 3735928559, extmap-allow-mixed: false, extensions: [], c_name: }, rtcp_report_interval_ms: 5000, send_transport: (Transport), media_transport_config: {media_transport: null}, min_bitrate_bps: -1, max_bitrate_bps: -1, send_codec_spec: {nack_enabled: false, transport_cc_enabled: false, cng_payload_type: <unset>, payload_type: 103, format: {name: opus, clockrate_hz: 48000, num_channels: 2, parameters: {stereo: 1}}}} (audio_encoder_opus.cc:767): Set Opus bitrate to 64000 bps. (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=up (rtp_transport_controller_send.cc:268): SignalNetworkState Up (neteq_impl.cc:123): NetEq config: sample_rate_hz=16000, enable_post_decode_vad=true, max_packets_in_buffer=200, min_delay_ms=0, enable_fast_accelerate=false, enable_muted_state=true, enable_rtx_handling=false (rtp_transport_controller_send.cc:462): Creating fallback congestion controller (audio_coding_module.cc:311): Created (audio_receive_stream.cc:117): AudioReceiveStream: 3735928559 (audio_receive_stream.cc:361): AudioReceiveStream::ConfigureStream: {rtp: {remote_ssrc: 3735928559, local_ssrc: 19088743, transport_cc: off, nack: {rtp_history_ms: 0}, extensions: []}, rtcp_send_transport: (Transport), media_traINFO:root:Running ['/b/s/w/ir/tools_webrtc/audio_quality/linux/PolqaOem64', '-q', '-LC', 'NB', '-Ref', './../audio_tiny48.wav', '-Test', './../LowBandwidth_GoodNetworkHighBitrate_48.wav'] nsport_config: {media_transport: null}} (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=up (rtp_transport_controller_send.cc:268): SignalNetworkState Up (alr_experiment.cc:78): Using ALR experiment settings: pacing factor: 1, max pacer queue length: 2875, ALR start bandwidth usage percent: 80, ALR end budget level percent: 40, ALR end budget level percent: -60, ALR experiment group ID: 3 (trendline_estimator.cc:121): Using Trendline filter for delay change estimation with window size 20 (aimd_rate_control.cc:105): Using aimd rate control with back off factor 0.85 (delay_based_bwe.cc:267): BWE Setting start bitrate to: 300 kbps (rtp_transport_controller_send.cc:462): Creating fallback congestion controller (probe_controller.cc:266): Measured bitrate: 300000 Minimum to probe further: 1260000 (bitrate_prober.cc:114): Probe cluster (bitrate:min bytes:min packets): (900000:1687:5) (bitrate_prober.cc:114): Probe cluster (bitrate:min bytes:min packets): (1800000:3375:5) (bitrate_allocator.cc:117): Current BWE 300000 (alr_experiment.cc:78): Using ALR experiment settings: pacing factor: 1, max pacer queue length: 2875, ALR start bandwidth usage percent: 80, ALR end budget level percent: 40, ALR end budget level percent: -60, ALR experiment group ID: 3 (trendline_estimator.cc:121): Using Trendline filter for delay change estimation with window size 20 (aimd_rate_control.cc:105): Using aimd rate control with back off factor 0.85 (delay_based_bwe.cc:267): BWE Setting start bitrate to: 300 kbps (probe_controller.cc:266): Measured bitrate: 300000 Minimum to probe further: 1260000 (bitrate_prober.cc:114): Probe cluster (bitrate:min bytes:min packets): (900000:1687:5) (bitrate_prober.cc:114): Probe cluster (bitrate:min bytes:min packets): (1800000:3375:5) (bitrate_allocator.cc:117): Current BWE 300000 (rtp_sender_audio.cc:260): First audio RTP packet sent to pacer (probe_controller.cc:364): kWaitingForProbingResult: timeout (probe_controller.cc:364): kWaitingForProbingResult: timeout (fake_network_pipe.cc:212): Network queue: 5 ms. (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=down (rtp_transport_controller_send.cc:268): SignalNetworkState Down (audio_send_stream.cc:179): ~AudioSendStream: 3735928559 (paced_sender.cc:106): PacedSender paused. (control_handler.cc:77): Bitrate estimate state changed, BWE: 300 kbps. (bitrate_allocator.cc:117): Current BWE 0 (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=down (rtp_transport_controller_send.cc:268): SignalNetworkState Down (audio_receive_stream.cc:140): ~AudioReceiveStream: 3735928559 (paced_sender.cc:106): PacedSender paused. (control_handler.cc:77): Bitrate estimate state changed, BWE: 300 kbps. (bitrate_allocator.cc:117): Current BWE 0 (paced_sender.cc:421): ProcessThreadAttached 0x0 (paced_sender.cc:421): ProcessThreadAttached 0x0 (paced_sender.cc:421): ProcessThreadAttached 0x0 (paced_sender.cc:421): ProcessThreadAttached 0x0 TEST GoodNetworkHighBitrate /b/s/w/ir/resources/voice_engine/audio_tiny48.wav /b/s/w/ir/out/LowBandwidth_GoodNetworkHighBitrate_48.wav RESULT polqa_mos_lqo: GoodNetworkHighBitrate= 4.5000 score [ OK ] LowBandwidthAudioTest.GoodNetworkHighBitrate (5913 ms) [ RUN ] LowBandwidthAudioTest.Mobile2GNetwork (audio_processing_impl.cc:435): Capture analyzer activated: 0 Capture post processor activated: 0 Render pre processor activated: 0 (audio_processing_impl.cc:435): Capture analyzer activated: 0 Capture post processor activated: 0 Render pre processor activated: 0 (bitrate_prober.cc:66): Bandwidth probing enabled, set to inactive (paced_sender.cc:421): ProcessThreadAttached 0x3009b030 (aimd_rate_control.cc:105): Using aimd rate control with back off factor 0.85 (remote_bitrate_estimator_single_stream.cc:71): RemoteBitrateEstimatorSingleStream: Instantiating. (remote_estimator_proxy.cc:44): Maximum interval between transport feedback RTCP messages (ms): 250 (bitrate_prober.cc:66): Bandwidth probing enabled, set to inactive (paced_sender.cc:421): ProcessThreadAttached 0x3009f760 (aimd_rate_control.cc:105): Using aimd rate control with back off factor 0.85 (remote_bitrate_estimator_single_stream.cc:71): RemoteBitrateEstimatorSingleStream: Instantiating. (remote_estimator_proxy.cc:44): Maximum interval between transport feedback RTCP messages (ms): 250 (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=down (rtp_transport_controller_send.cc:268): SignalNetworkState Down (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=down (rtp_transport_controller_send.cc:268): SignalNetworkState Down (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=down (rtp_transport_controller_send.cc:268): SignalNetworkState Down (neteq_impl.cc:123): NetEq config: sample_rate_hz=16000, enable_post_decode_vad=true, max_packets_in_buffer=200, min_delay_ms=0, enable_fast_accelerate=false, enable_muted_state=false, enable_rtx_handling=false (audio_coding_module.cc:311): Created (audio_send_stream.cc:142): AudioSendStream: 3735928559 (audio_send_stream.cc:230): AudioSendStream::ConfigureStream: {rtp: {ssrc: 3735928559, extmap-allow-mixed: false, extensions: [], c_name: }, rtcp_report_interval_ms: 5000, send_transport: (Transport), media_transport_config: {media_transport: null}, min_bitrate_bps: -1, max_bitrate_bps: -1, send_codec_spec: {nack_enabled: false, transport_cc_enabled: false, cng_payload_type: <unset>, payload_type: 103, format: {name: OPUS, clockrate_hz: 48000, num_channels: 2, parameters: {maxaveragebitrate: 6000, ptime: 60, stereo: 1}}}} (audio_encoder_opus.cc:767): Set Opus bitrate to 6000 bps. (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=up (rtp_transport_controller_send.cc:268): SignalNetworkState Up (neteq_impl.cc:123): NetEq config: sample_rate_hz=16000, enable_post_decode_vad=true, max_packets_in_buffer=200, min_delay_ms=0, enable_fast_accelerate=false, enable_muted_state=true, enable_rtx_handling=false (rtp_transport_controller_send.cc:462): Creating fallback congestion controller (audio_coding_module.cc:311): Created (audio_receive_stream.cc:117): AudioReceiveStream: 3735928559 (audio_receive_stream.cc:361): AudioReceiveStream::ConfigureStream: {rtp: {remote_ssrc: 3735928559, local_ssrc: 19088743, transport_cc: off, nack: {rtp_history_ms: 0}, extensions: []}, rtcp_send_transport: (Transport), media_transport_config: {media_transport: null}} (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=up (rtp_transport_controller_send.cc:268): SignalNetworkState Up (alr_experiment.cc:78): Using ALR experiment settings: pacing factor: 1, max pacer queue length: 2875, ALR start bandwidth usage percent: 80, ALR end budget level percent: 40, ALR end budget level percent: -60, ALR experiment group ID: 3 (trendline_estimator.cc:121): Using Trendline filter for delay change estimation with window size 20 (aimd_rate_control.cc:105): Using aimd rate control with back off factor 0.85 (delay_based_bwe.cc:267): BWE Setting start bitrate to: 300 kbps (probe_controller.cc:266): Measured bitrate: 300000 Minimum to probe further: 1260000 (rtp_transport_controller_send.cc:462): Creating fallback congestion controller (bitrate_prober.cc:114): Probe cluster (bitrate:min bytes:min packets): (900000:1687:5) (bitrate_prober.cc:114): Probe cluster (bitrate:min bytes:min packets): (1800000:3375:5) (bitrate_allocator.cc:117): Current BWE 300000 (alr_experiment.cc:78): Using ALR experiment settings: pacing factor: 1, max pacer queue length: 2875, ALR start bandwidth usage percent: 80, ALR end budget level percent: 40, ALR end budget level percent: -60, ALR experiment group ID: 3 (trendline_estimator.cc:121): Using Trendline filter for delay change estimation with window size 20 (aimd_rate_control.cc:105): Using aimd rate control with back off factor 0.85 (delay_based_bwe.cc:267): BWE Setting start bitrate to: 300 kbps (probe_controller.cc:266): Measured bitrate: 300000 Minimum to probe further: 1260000 (bitrate_prober.cc:114): Probe cluster (bitrate:min bytes:min packets): (900000:1687:5) (bitrate_prober.cc:114): Probe cluster (bitrate:min bytes:min packets): (1800000:3375:5) (bitrate_allocator.cc:117): Current BWE 300000 (rtpINFO:root:Running ['/b/s/w/ir/tools_webrtc/audio_quality/linux/PolqaOem64', '-q', '-LC', 'NB', '-Ref', './../audio_tiny48.wav', '-Test', './../LowBandwidth_Mobile2GNetwork_48.wav'] _sender_audio.cc:260): First audio RTP packet sent to pacer (probe_controller.cc:364): kWaitingForProbingResult: timeout (probe_controller.cc:364): kWaitingForProbingResult: timeout (fake_network_pipe.cc:212): Network queue: 460 ms. (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=down (rtp_transport_controller_send.cc:268): SignalNetworkState Down (audio_send_stream.cc:179): ~AudioSendStream: 3735928559 (paced_sender.cc:106): PacedSender paused. (control_handler.cc:77): Bitrate estimate state changed, BWE: 300 kbps. (bitrate_allocator.cc:117): Current BWE 0 (call.cc:1169): UpdateAggregateNetworkState: aggregate_state=down (rtp_transport_controller_send.cc:268): SignalNetworkState Down (audio_receive_stream.cc:140): ~AudioReceiveStream: 3735928559 (paced_sender.cc:106): PacedSender paused. (control_handler.cc:77): Bitrate estimate state changed, BWE: 300 kbps. (bitrate_allocator.cc:117): Current BWE 0 (paced_sender.cc:421): ProcessThreadAttached 0x0 (paced_sender.cc:421): ProcessThreadAttached 0x0 (paced_sender.cc:421): ProcessThreadAttached 0x0 (paced_sender.cc:421): ProcessThreadAttached 0x0 TEST Mobile2GNetwork /b/s/w/ir/resources/voice_engine/audio_tiny48.wav /b/s/w/ir/out/LowBandwidth_Mobile2GNetwork_48.wav RESULT polqa_mos_lqo: Mobile2GNetwork= 3.0963 score [ OK ] LowBandwidthAudioTest.Mobile2GNetwork (6314 ms) [----------] 2 tests from LowBandwidthAudioTest (12227 ms total) [----------] Global test environment tear-down [==========] 2 tests from 1 test suite ran. (12227 ms total) [ PASSED ] 2 tests. 2019-05-25 07:40:55,655 - root: [DEBUG] Contents of task_output_dir: ['/b/swarming/w/ir/tmp/t/tmpYufjOA/4506bfe548c1a410'] 2019-05-25 07:40:55,656 - root: [DEBUG] Found shard_json_files: ['/b/swarming/w/ir/tmp/t/tmpYufjOA/4506bfe548c1a410/output.json'] 2019-05-25 07:40:55,656 - root: [INFO] merge_cmd: /b/swarming/w/ir/cache/vpython/a3677d/bin/python /b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_isolated_script_merge.py --summary-json /b/swarming/w/ir/tmp/t/tmpMFCle2.json --task-output-dir /b/swarming/w/ir/tmp/t/tmpYufjOA -o /b/swarming/w/ir/tmp/t/tmpTs7xOF.json /b/swarming/w/ir/tmp/t/tmpYufjOA/4506bfe548c1a410/output.json Running ['/b/swarming/w/ir/cache/vpython/a3677d/bin/python', '/b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_isolated_script_merge.py', '--summary-json', '/b/swarming/w/ir/tmp/t/tmpMFCle2.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpYufjOA', '-o', '/b/swarming/w/ir/tmp/t/tmpTs7xOF.json', '/b/swarming/w/ir/tmp/t/tmpYufjOA/4506bfe548c1a410/output.json'] in None (env: None) Command ['/b/swarming/w/ir/cache/vpython/a3677d/bin/python', '/b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_isolated_script_merge.py', '--summary-json', '/b/swarming/w/ir/tmp/t/tmpMFCle2.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpYufjOA', '-o', '/b/swarming/w/ir/tmp/t/tmpTs7xOF.json', '/b/swarming/w/ir/tmp/t/tmpYufjOA/4506bfe548c1a410/output.json'] returned exit code 0