Nov 16 12:26:18.434 INFO testing starrhorne/nes-rust against master#6b9b97bd9b704f85f0184f7a213cc4d62bd9654c for pr-55982
Nov 16 12:26:18.434 INFO running `"docker" "create" "-v" "/mnt/big/crater/work/local/target-dirs/pr-55982/worker-5/master#6b9b97bd9b704f85f0184f7a213cc4d62bd9654c:/target:rw,Z" "-v" "/mnt/big/crater/work/local/test-source/worker-5/pr-55982/master#6b9b97bd9b704f85f0184f7a213cc4d62bd9654c:/source:ro,Z" "-v" "/mnt/big/crater/work/local/cargo-home:/cargo-home:ro,Z" "-v" "/mnt/big/crater/work/local/rustup-home:/rustup-home:ro,Z" "-e" "USER_ID=1000" "-e" "SOURCE_DIR=/source" "-e" "USER_ID=1000" "-e" "CMD=cargo +6b9b97bd9b704f85f0184f7a213cc4d62bd9654c-alt build --frozen" "-e" "CARGO_TARGET_DIR=/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/cargo-home" "-e" "RUSTUP_HOME=/rustup-home" "-m" "1536M" "--network" "none" "crater"`
Nov 16 12:26:18.891 INFO [stdout] 862ad9cf71c847daf8e0b30555b30855f0a4c042a932ed71275f2035b5e5c11b
Nov 16 12:26:18.893 INFO running `"docker" "start" "-a" "862ad9cf71c847daf8e0b30555b30855f0a4c042a932ed71275f2035b5e5c11b"`
Nov 16 12:26:20.615 INFO [stderr] usermod: no changes
Nov 16 12:26:20.711 INFO [stderr]    Compiling bitfield v0.12.0
Nov 16 12:26:20.712 INFO [stderr]    Compiling libretro-sys v0.1.0
Nov 16 12:26:20.716 INFO [stderr]    Compiling time v0.1.39
Nov 16 12:26:20.723 INFO [stderr]    Compiling rand v0.3.17
Nov 16 12:26:22.681 INFO [stderr]    Compiling libretro-backend v0.2.1
Nov 16 12:26:23.922 INFO [stderr]    Compiling nes v0.1.0 (/source)
Nov 16 12:26:26.168 INFO [stderr]     Finished dev [unoptimized + debuginfo] target(s) in 5.51s
Nov 16 12:26:26.172 INFO [stderr] su: No module specific data is present
Nov 16 12:26:26.573 INFO running `"docker" "inspect" "862ad9cf71c847daf8e0b30555b30855f0a4c042a932ed71275f2035b5e5c11b"`
Nov 16 12:26:26.756 INFO running `"docker" "rm" "-f" "862ad9cf71c847daf8e0b30555b30855f0a4c042a932ed71275f2035b5e5c11b"`
Nov 16 12:26:26.995 INFO [stdout] 862ad9cf71c847daf8e0b30555b30855f0a4c042a932ed71275f2035b5e5c11b
Nov 16 12:26:27.002 INFO running `"docker" "create" "-v" "/mnt/big/crater/work/local/target-dirs/pr-55982/worker-5/master#6b9b97bd9b704f85f0184f7a213cc4d62bd9654c:/target:rw,Z" "-v" "/mnt/big/crater/work/local/test-source/worker-5/pr-55982/master#6b9b97bd9b704f85f0184f7a213cc4d62bd9654c:/source:ro,Z" "-v" "/mnt/big/crater/work/local/cargo-home:/cargo-home:ro,Z" "-v" "/mnt/big/crater/work/local/rustup-home:/rustup-home:ro,Z" "-e" "USER_ID=1000" "-e" "SOURCE_DIR=/source" "-e" "USER_ID=1000" "-e" "CMD=cargo +6b9b97bd9b704f85f0184f7a213cc4d62bd9654c-alt test --frozen --no-run" "-e" "CARGO_TARGET_DIR=/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/cargo-home" "-e" "RUSTUP_HOME=/rustup-home" "-m" "1536M" "--network" "none" "crater"`
Nov 16 12:26:27.449 INFO [stdout] 8783ec2016670bcb0b64ca874c529558f88e7524db03e03916df57afd1aa2a13
Nov 16 12:26:27.452 INFO running `"docker" "start" "-a" "8783ec2016670bcb0b64ca874c529558f88e7524db03e03916df57afd1aa2a13"`
Nov 16 12:26:28.515 INFO [stderr] usermod: no changes
Nov 16 12:26:28.611 INFO [stderr]    Compiling nes v0.1.0 (/source)
Nov 16 12:26:30.223 INFO [stderr] warning: unused import: `apu::Apu`
Nov 16 12:26:30.223 INFO [stderr]  --> src/./cpu_test.rs:3:5
Nov 16 12:26:30.223 INFO [stderr]   |
Nov 16 12:26:30.224 INFO [stderr] 3 | use apu::Apu;
Nov 16 12:26:30.224 INFO [stderr]   |     ^^^^^^^^
Nov 16 12:26:30.224 INFO [stderr]   |
Nov 16 12:26:30.225 INFO [stderr]   = note: #[warn(unused_imports)] on by default
Nov 16 12:26:30.225 INFO [stderr] 
Nov 16 12:26:30.225 INFO [stderr] warning: unused import: `ppu::Ppu`
Nov 16 12:26:30.226 INFO [stderr]  --> src/./cpu_test.rs:6:5
Nov 16 12:26:30.226 INFO [stderr]   |
Nov 16 12:26:30.226 INFO [stderr] 6 | use ppu::Ppu;
Nov 16 12:26:30.226 INFO [stderr]   |     ^^^^^^^^
Nov 16 12:26:30.227 INFO [stderr] 
Nov 16 12:26:30.227 INFO [stderr] warning: unused macro definition
Nov 16 12:26:30.227 INFO [stderr]   --> src/./cpu_test.rs:44:1
Nov 16 12:26:30.228 INFO [stderr]    |
Nov 16 12:26:30.228 INFO [stderr] 44 | / macro_rules! build_cpu_and_run {
Nov 16 12:26:30.228 INFO [stderr] 45 | |     ($instruction:expr, $mode:ident, $bytes:expr) => {
Nov 16 12:26:30.228 INFO [stderr] 46 | |         {
Nov 16 12:26:30.229 INFO [stderr] 47 | |             let op = opcode($instruction, $mode);
Nov 16 12:26:30.229 INFO [stderr] ...  |
Nov 16 12:26:30.229 INFO [stderr] 60 | |     }
Nov 16 12:26:30.229 INFO [stderr] 61 | | }
Nov 16 12:26:30.230 INFO [stderr]    | |_^
Nov 16 12:26:30.230 INFO [stderr]    |
Nov 16 12:26:30.230 INFO [stderr]    = note: #[warn(unused_macros)] on by default
Nov 16 12:26:30.231 INFO [stderr] 
Nov 16 12:26:30.263 INFO [stderr] warning: unused import: `super::*`
Nov 16 12:26:30.267 INFO [stderr]    --> src/bus.rs:203:9
Nov 16 12:26:30.267 INFO [stderr]     |
Nov 16 12:26:30.267 INFO [stderr] 203 |     use super::*;
Nov 16 12:26:30.267 INFO [stderr]     |         ^^^^^^^^
Nov 16 12:26:30.267 INFO [stderr] 
Nov 16 12:26:45.747 INFO [stderr]     Finished dev [unoptimized + debuginfo] target(s) in 17.19s
Nov 16 12:26:45.755 INFO [stderr] su: No module specific data is present
Nov 16 12:26:47.263 INFO running `"docker" "inspect" "8783ec2016670bcb0b64ca874c529558f88e7524db03e03916df57afd1aa2a13"`
Nov 16 12:26:47.565 INFO running `"docker" "rm" "-f" "8783ec2016670bcb0b64ca874c529558f88e7524db03e03916df57afd1aa2a13"`
Nov 16 12:26:47.814 INFO [stdout] 8783ec2016670bcb0b64ca874c529558f88e7524db03e03916df57afd1aa2a13
Nov 16 12:26:47.818 INFO running `"docker" "create" "-v" "/mnt/big/crater/work/local/target-dirs/pr-55982/worker-5/master#6b9b97bd9b704f85f0184f7a213cc4d62bd9654c:/target:rw,Z" "-v" "/mnt/big/crater/work/local/test-source/worker-5/pr-55982/master#6b9b97bd9b704f85f0184f7a213cc4d62bd9654c:/source:ro,Z" "-v" "/mnt/big/crater/work/local/cargo-home:/cargo-home:ro,Z" "-v" "/mnt/big/crater/work/local/rustup-home:/rustup-home:ro,Z" "-e" "USER_ID=1000" "-e" "SOURCE_DIR=/source" "-e" "USER_ID=1000" "-e" "CMD=cargo +6b9b97bd9b704f85f0184f7a213cc4d62bd9654c-alt test --frozen" "-e" "CARGO_TARGET_DIR=/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/cargo-home" "-e" "RUSTUP_HOME=/rustup-home" "-m" "1536M" "--network" "none" "crater"`
Nov 16 12:26:48.306 INFO [stdout] f41f1f7eaa383dd82fbbb1d20d2ef110d7c4d13f8d48f9fb445a78c1fa7f7db1
Nov 16 12:26:48.309 INFO running `"docker" "start" "-a" "f41f1f7eaa383dd82fbbb1d20d2ef110d7c4d13f8d48f9fb445a78c1fa7f7db1"`
Nov 16 12:26:50.043 INFO [stderr] usermod: no changes
Nov 16 12:26:50.202 INFO [stderr]     Finished dev [unoptimized + debuginfo] target(s) in 0.11s
Nov 16 12:26:50.203 INFO [stderr]      Running /target/debug/deps/nes-b4bea5e443d65cca
Nov 16 12:26:50.209 INFO [stdout] 
Nov 16 12:26:50.209 INFO [stdout] running 119 tests
Nov 16 12:26:50.211 INFO [stdout] test cartridge::cartridge_header::test::test_sizes ... ok
Nov 16 12:26:50.219 INFO [stdout] test cartridge::mapper1::test::test_shift ... ok
Nov 16 12:26:50.389 INFO [stdout] test cartridge::pager::test::test_index_first ... ok
Nov 16 12:26:50.412 INFO [stdout] test cartridge::pager::test::test_index_last ... ok
Nov 16 12:26:50.527 INFO [stdout] test cartridge::mapper1::test::test_set_chr_1 ... ok
Nov 16 12:26:50.570 INFO [stdout] test cartridge::pager::test::test_index_number ... ok
Nov 16 12:26:50.784 INFO [stdout] test cartridge::mapper1::test::test_set_chr_0 ... ok
Nov 16 12:26:50.791 INFO [stdout] test cartridge::mapper1::test::test_set_prg ... ok
Nov 16 12:26:50.792 INFO [stdout] test cartridge::mapper1::test::test_chr_rom ... ok
Nov 16 12:26:50.796 INFO [stdout] test cartridge::pager::test::test_page_count ... ok
Nov 16 12:26:50.796 INFO [stdout] test cartridge::pager::test::test_rw ... ok
Nov 16 12:26:50.807 INFO [stdout] test cartridge::ppu_test::test_chr_ram ... ok
Nov 16 12:26:50.808 INFO [stdout] test cartridge::ppu_test::test_prg_ram ... ok
Nov 16 12:26:50.819 INFO [stdout] test cartridge::ppu_test::test_read_chr_rom ... ok
Nov 16 12:26:50.831 INFO [stdout] test cartridge::ppu_test::test_read_prg_rom ... ok
Nov 16 12:26:50.832 INFO [stdout] test cartridge::mapper1::test::test_prg_rom ... ok
Nov 16 12:26:50.851 INFO [stdout] test cartridge::mapper1::test::test_set_control ... ok
Nov 16 12:26:50.937 INFO [stdout] test cpu::cpu_test::test_and ... ok
Nov 16 12:26:50.945 INFO [stdout] test cartridge::mapper1::test::test_prg_ram ... ok
Nov 16 12:26:50.999 INFO [stdout] test cpu::cpu_test::test_bcs ... ok
Nov 16 12:26:51.008 INFO [stdout] test cpu::cpu_test::test_bit ... ok
Nov 16 12:26:51.058 INFO [stdout] test cpu::cpu_test::test_adc ... ok
Nov 16 12:26:51.064 INFO [stdout] test cpu::cpu_test::test_bcc ... ok
Nov 16 12:26:51.072 INFO [stdout] test cpu::cpu_test::test_brk ... ok
Nov 16 12:26:51.092 INFO [stdout] test cpu::cpu_test::test_asl ... ok
Nov 16 12:26:51.140 INFO [stdout] test cpu::cpu_test::test_beq ... ok
Nov 16 12:26:51.176 INFO [stdout] test cpu::cpu_test::test_bvc ... ok
Nov 16 12:26:51.177 INFO [stdout] test cpu::cpu_test::test_bpl ... ok
Nov 16 12:26:51.200 INFO [stdout] test cpu::cpu_test::test_bmi ... ok
Nov 16 12:26:51.208 INFO [stdout] test cpu::cpu_test::test_bne ... ok
Nov 16 12:26:51.215 INFO [stdout] test cpu::cpu_test::test_bvs ... ok
Nov 16 12:26:51.217 INFO [stdout] test cpu::cpu_test::test_cmp ... ok
Nov 16 12:26:51.276 INFO [stdout] test cpu::cpu_test::test_cpx ... ok
Nov 16 12:26:51.280 INFO [stdout] test cpu::cpu_test::test_dec ... ok
Nov 16 12:26:51.281 INFO [stdout] test cpu::cpu_test::test_cpy ... ok
Nov 16 12:26:51.282 INFO [stdout] test cpu::cpu_test::test_dex ... ok
Nov 16 12:26:51.336 INFO [stdout] test cpu::cpu_test::test_dey ... ok
Nov 16 12:26:51.340 INFO [stdout] test cpu::cpu_test::test_eor ... ok
Nov 16 12:26:51.386 INFO [stdout] test cpu::cpu_test::test_jsr_ret ... ok
Nov 16 12:26:51.396 INFO [stdout] test cpu::cpu_test::test_inx ... ok
Nov 16 12:26:51.400 INFO [stdout] test cpu::cpu_test::test_flag_ops ... ok
Nov 16 12:26:51.412 INFO [stdout] test cpu::cpu_test::test_inc ... ok
Nov 16 12:26:51.413 INFO [stdout] test cpu::cpu_test::test_iny ... ok
Nov 16 12:26:51.448 INFO [stdout] test cpu::cpu_test::test_jmp ... ok
Nov 16 12:26:51.452 INFO [stdout] test cpu::cpu_test::test_lda ... ok
Nov 16 12:26:51.456 INFO [stdout] test cpu::cpu_test::test_ldy ... ok
Nov 16 12:26:51.468 INFO [stdout] test cpu::cpu_test::test_ldx ... ok
Nov 16 12:26:51.472 INFO [stdout] test cpu::cpu_test::test_lsr ... ok
Nov 16 12:26:51.473 INFO [stdout] test cpu::cpu_test::test_ror ... ok
Nov 16 12:26:51.493 INFO [stdout] test cpu::cpu_test::test_ora ... ok
Nov 16 12:26:51.494 INFO [stdout] test cpu::cpu_test::test_pha_pla ... ok
Nov 16 12:26:51.512 INFO [stdout] test cpu::cpu_test::test_php_plp ... ok
Nov 16 12:26:51.519 INFO [stdout] test cpu::cpu_test::test_tax ... ok
Nov 16 12:26:51.559 INFO [stdout] test cpu::cpu_test::test_rol ... ok
Nov 16 12:26:51.571 INFO [stdout] test cpu::cpu_test::test_sta ... ok
Nov 16 12:26:51.587 INFO [stdout] test cpu::cpu_test::test_txa ... ok
Nov 16 12:26:51.607 INFO [stdout] test cartridge::pager::test::test_index_nopage ... ok
Nov 16 12:26:51.607 INFO [stdout] test cpu::cpu_test::test_sbc ... ok
Nov 16 12:26:51.608 INFO [stdout] test cpu::cpu_test::test_tsx ... ok
Nov 16 12:26:51.608 INFO [stdout] test cpu::cpu_test::test_tay ... ok
Nov 16 12:26:51.608 INFO [stdout] test cpu::cpu_test::test_stx ... ok
Nov 16 12:26:51.609 INFO [stdout] test cpu::cpu_test::test_sty ... ok
Nov 16 12:26:51.609 INFO [stdout] test cpu::cpu_test::test_txs ... ok
Nov 16 12:26:51.609 INFO [stdout] test ppu::address::test::test_copy_y ... ok
Nov 16 12:26:51.610 INFO [stdout] test ppu::address::test::test_attribute_address ... ok
Nov 16 12:26:51.610 INFO [stdout] test ppu::address::test::test_register_address ... ok
Nov 16 12:26:51.610 INFO [stdout] test ppu::address::test::test_scroll_x ... ok
Nov 16 12:26:51.611 INFO [stdout] test ppu::address::test::test_tile_offset ... ok
Nov 16 12:26:51.611 INFO [stdout] test ppu::address::test::test_scroll_y ... ok
Nov 16 12:26:51.611 INFO [stdout] test ppu::control::test::test_increment_amount ... ok
Nov 16 12:26:51.612 INFO [stdout] test ppu::address::test::test_loopy ... ok
Nov 16 12:26:51.612 INFO [stdout] test ppu::address::test::test_nametable_address ... ok
Nov 16 12:26:51.612 INFO [stdout] test ppu::control::test::test_background_tile_base ... ok
Nov 16 12:26:51.613 INFO [stdout] test ppu::address::test::test_copy_x ... ok
Nov 16 12:26:51.613 INFO [stdout] test cartridge::pager::test::test_index_overflow ... ok
Nov 16 12:26:51.613 INFO [stdout] test cpu::cpu_test::test_tya ... ok
Nov 16 12:26:51.614 INFO [stdout] test ppu::mask::test::test_rendering_sprites ... ok
Nov 16 12:26:51.614 INFO [stdout] test ppu::registers::test::test_read_data_delayed ... ok
Nov 16 12:26:51.614 INFO [stdout] test ppu::mask::test::test_rendering_background ... ok
Nov 16 12:26:51.615 INFO [stdout] test ppu::registers::test::test_read_ghost_bits ... ok
Nov 16 12:26:51.615 INFO [stdout] test ppu::registers::test::test_read_oam_data ... ok
Nov 16 12:26:51.616 INFO [stdout] test ppu::registers::test::test_read_status ... ok
Nov 16 12:26:51.616 INFO [stdout] test ppu::control::test::test_sprite_tile_base ... ok
Nov 16 12:26:51.616 INFO [stdout] test ppu::control::test::test_sprite_height ... ok
Nov 16 12:26:51.617 INFO [stdout] test ppu::registers::test::test_write_control ... ok
Nov 16 12:26:51.617 INFO [stdout] test ppu::registers::test::test_write_data ... ok
Nov 16 12:26:51.617 INFO [stdout] test ppu::registers::test::test_write_mask ... ok
Nov 16 12:26:51.618 INFO [stdout] test ppu::registers::test::test_write_oam_address ... ok
Nov 16 12:26:51.618 INFO [stdout] test ppu::registers::test::test_write_oam_data ... ok
Nov 16 12:26:51.618 INFO [stdout] test ppu::registers::test::test_write_scroll ... ok
Nov 16 12:26:51.619 INFO [stdout] test ppu::registers::test::test_write_address ... ok
Nov 16 12:26:51.619 INFO [stdout] test ppu::renderer::test::test_evaluate_sprites ... ok
Nov 16 12:26:51.619 INFO [stdout] test ppu::renderer::test::test_load_sprites ... ok
Nov 16 12:26:51.620 INFO [stdout] test ppu::renderer::test::test_reload_shift ... ok
Nov 16 12:26:51.620 INFO [stdout] test ppu::renderer::test::test_render_background_pixel ... ok
Nov 16 12:26:51.620 INFO [stdout] test ppu::renderer::test::test_render_pixel_opaque_sprite_behind ... ok
Nov 16 12:26:51.621 INFO [stdout] test ppu::renderer::test::test_render_pixel_opaque_sprite_front ... ok
Nov 16 12:26:51.621 INFO [stdout] test ppu::renderer::test::test_render_pixel_transparent_sprite_front ... ok
Nov 16 12:26:51.621 INFO [stdout] test ppu::renderer::test::test_render_sprite_pixel ... ok
Nov 16 12:26:51.621 INFO [stdout] test ppu::renderer::test::test_shift ... ok
Nov 16 12:26:51.622 INFO [stdout] test ppu::renderer::test::test_sprite_overflow ... ok
Nov 16 12:26:51.622 INFO [stdout] test ppu::renderer::test::test_step ... ok
Nov 16 12:26:51.625 INFO [stdout] test ppu::sprite::test::test_color_index ... ok
Nov 16 12:26:51.625 INFO [stdout] test ppu::sprite::test::test_color_index_flip_x ... ok
Nov 16 12:26:51.625 INFO [stdout] test ppu::sprite::test::test_sprite_tile_offset ... ok
Nov 16 12:26:51.626 INFO [stdout] test ppu::sprite::test::test_tile_address_large_flip_y ... ok
Nov 16 12:26:51.626 INFO [stdout] test ppu::sprite::test::test_tile_address_large_no_flip ... ok
Nov 16 12:26:51.626 INFO [stdout] test ppu::sprite::test::test_tile_address_small_flip_y ... ok
Nov 16 12:26:51.627 INFO [stdout] test ppu::sprite::test::test_tile_address_small_no_flip ... ok
Nov 16 12:26:51.627 INFO [stdout] test ppu::sprite::test::test_tile_base ... ok
Nov 16 12:26:51.627 INFO [stdout] test ppu::vram::test::test_buffered_read_byte ... ok
Nov 16 12:26:51.628 INFO [stdout] test ppu::vram::test::test_mirror_nametable_horizontally ... ok
Nov 16 12:26:51.628 INFO [stdout] test ppu::vram::test::test_mirror_nametable_vertically ... ok
Nov 16 12:26:51.628 INFO [stdout] test ppu::vram::test::test_mirror_palette ... ok
Nov 16 12:26:51.629 INFO [stdout] test ppu::vram::test::test_read_byte_cartridge ... ok
Nov 16 12:26:51.629 INFO [stdout] test ppu::vram::test::test_read_byte_nametable ... ok
Nov 16 12:26:51.629 INFO [stdout] test ppu::vram::test::test_read_byte_palette ... ok
Nov 16 12:26:51.630 INFO [stdout] test ppu::vram::test::test_write_byte_nametable ... ok
Nov 16 12:26:51.630 INFO [stdout] test ppu::vram::test::test_write_byte_palette ... ok
Nov 16 12:26:51.630 INFO [stdout] 
Nov 16 12:26:51.635 INFO [stdout] test result: ok. 119 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
Nov 16 12:26:51.635 INFO [stdout] 
Nov 16 12:26:51.639 INFO [stderr] su: No module specific data is present
Nov 16 12:26:52.597 INFO running `"docker" "inspect" "f41f1f7eaa383dd82fbbb1d20d2ef110d7c4d13f8d48f9fb445a78c1fa7f7db1"`
Nov 16 12:26:52.885 INFO running `"docker" "rm" "-f" "f41f1f7eaa383dd82fbbb1d20d2ef110d7c4d13f8d48f9fb445a78c1fa7f7db1"`
Nov 16 12:26:53.303 INFO [stdout] f41f1f7eaa383dd82fbbb1d20d2ef110d7c4d13f8d48f9fb445a78c1fa7f7db1