panicked at 'called Result::unwrap() on an Err

[ritiek]

panicked at 'called Result::unwrap() on an Err

[andy5995]

@ritiek @Jammyjamjamman found that some packets from another device on my network were interfering. It turned out to be my Google Home mini. After I blocked its IP on my LAN, he couldn't reproduce the crash.

Note that I was still crashing before when trying your suggestion of using '--receiver-address=127.0.0.1:6347'... so I guess the Google thing was sending packets to quite a variety of ports!

[ritiek]

Alright, I see.

@ritiek I suggest that you run cargo clippy. I get over 30 warnings when I do that. Maybe fixing some of them would make it easier to debug.

Ok, will do this.

[Jammyjamjamman]

Me and Andy used tcpdump to listen to the udp port the piano binds to, while using the piano. We could see the packets that are sent when pressing piano keys. However, interestingly, the rouge packet the piano kept receiving on Andy's computer was not picked up by tcpdump.

So the piano game is picking up data in the udp buffer, but it's unclear where it's coming from. We modified the piano program to spit out the buf contents in the receiver, when it causes the bincode decoder to panic. This is the content of the buffer when it causes the piano receiver on Andy's computer to crash:

[D0, F2, 81, F8, 8B, FF, 9A, F7, D5, EF, 94, B6, D1, B4, C0, 9F, EC, 95, E6, 8F, E1, 87, E8, CA, F0, 8B, F6, 8B, F6, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00]

(N.b. I cannot reproduce this bug on my laptop, running Manjaro, kernel 5.9-11, rustc 1.48.0.)

[ritiek]

Interesting. What do you see when you print the value of ``src` in

piano-rs/src/network/receiver.rs

Line 23 in 5509a9e

let (amt, src) = self.socket.recv_from(&mut buf)?;

Either way, I'll add checks to make sure to proceed only if the network data received is valid. That should probably fix this.

[jmanabc]

I have the same issue on Manjaro with rust 1.48.0

[ritiek]

This is weird. I'm not really sure what would be causing this. Can you guys provide more information on how exactly are you running the game?

I have the same issue on Manjaro with rust 1.48.0

I'm on Manjaro at the moment too and $ rustc -V gives me rustc 1.48.0 (7eac88abb 2020-11-16), but I am able to compile and played music for 10 minutes straight without any problem with:

$ git clone https://github.com/ritiek/piano-rs
$ cd piano-rs
$ cargo run --release

Also, is there any pattern to when the traceback happens? Or does it apparently happen randomly on some key press?

[andy5995]

No pattern that I could tell.. Happens within a minute.

Here's the output when I run RUST_BACKTRACE=full ./target/debug/piano-rs

https://gist.githubusercontent.com/andy5995/70ae708a3a32ba90e0325edf35ce42db/raw/12a7e2a66656840d91a18dfe78e7738679f0a57b/gistfile1.txt

And the output when I run RUST_BACKTRACE=full ./target/release/piano-rs (after using cargo build --release)

https://gist.githubusercontent.com/andy5995/d4e533fdfdaea37adc417490f681c730/raw/9d4d775909c2ebf4437a78a996278b42d12c1d9a/gistfile1.txt

I'm trying git rev 00f6c64 and building now with rustc 1.48.0 (7eac88abb 2020-11-16)

[andy5995]

I tried with the '-r' option. Another crash, but here are the recorded notes

https://gist.githubusercontent.com/andy5995/b6ce15841c0e1c98e7cb76e286a872a6/raw/96b5c2635d01ff6126a012f55bb74c8289a381e9/gistfile1.txt

On another try, crashed after only a few notes

note_1:
  - 1513
  - gs1
  - 0

note_2:
  - 671
  - as1
  - 0

note_3:
  - 1984
  - cs2
  - 0

[andy5995]

@ritiek I suggest that you run cargo clippy. I get over 30 warnings when I do that. Maybe fixing some of them would make it easier to debug.

[ritiek]

Could you guys try building it again from master branch? I fixed the clippy warnings and updated a few dependencies too, so let's see how that affects the traceback just in case if it does.

[andy5995]

Sorry to tell you, I have the same problem.

Here's some extra info (maybe it'll help troubleshooting later?)

andy@oceanus:~/src/rust/piano-rs/target/release$ ldd piano-rs
	linux-vdso.so.1 (0x00007ffd10bc0000)
	libasound.so.2 => /usr/lib/x86_64-linux-gnu/libasound.so.2 (0x00007fa834c83000)
	libgcc_s.so.1 => /lib/x86_64-linux-gnu/libgcc_s.so.1 (0x00007fa834c69000)
	libc.so.6 => /lib/x86_64-linux-gnu/libc.so.6 (0x00007fa834aa8000)
	/lib64/ld-linux-x86-64.so.2 (0x00007fa834f59000)
	libm.so.6 => /lib/x86_64-linux-gnu/libm.so.6 (0x00007fa834925000)
	libpthread.so.0 => /lib/x86_64-linux-gnu/libpthread.so.0 (0x00007fa834904000)
	libdl.so.2 => /lib/x86_64-linux-gnu/libdl.so.2 (0x00007fa8348ff000)
	librt.so.1 => /lib/x86_64-linux-gnu/librt.so.1 (0x00007fa8348f3000)

[ritiek]

Could you try passing --receiver-address=127.0.0.1:6347. It could be possible that the default bind address of 0.0.0.0:9999 is receiving data from another source (piano-rs does not validate this data at the moment so it should probably crash like it does in your case).

[andy5995]

No change. You might be able to reproduce the issue by pressing the semicolon or 'd' key while you're testing (the crash won't happen immediately).

[ritiek]

So weird. Still can't reproduce with what you suggested.

[andy5995]

Also happens when I play back a recorded file, but not every time. so far about 2/4 times. I first recorded the file and exited piano-rs with ESC before it crashed.

It played the notes, then after about 5-10 seconds, I got the error.

2020-12-20.18-58-07.mp4

note_1:
  - 2518
  - as2
  - 0

note_2:
  - 370
  - b2
  - 0

note_3:
  - 392
  - as2
  - 0

note_4:
  - 583
  - a2
  - 0

note_5:
  - 440
  - gs2
  - 0

note_6:
  - 415
  - g2
  - 0

note_7:
  - 479
  - as2
  - 0

note_8:
  - 399
  - b2
  - 0

note_9:
  - 368
  - as2
  - 0

note_10:
  - 431
  - a2
  - 0

note_11:
  - 392
  - gs2
  - 0

note_12:
  - 431
  - g2
  - 0

cc @Jammyjamjamman

[andy5995]

I've found I can reproduce the bug more predictably if I wait between key presses. Sometimes if I start the program and press no key, it will crash in ~10-120 seconds. Sometimes if I press one key, then wait several seconds it will crash. Or pressing 2 keys within ~10 seconds, then pressing no keys, a crash will happen.

[ritiek]

@andy5995 Could you try replacing this function here:

piano-rs/src/network/receiver.rs

Lines 19 to 31 in 5509a9e

	pub fn poll_event(&self) -> Result<types::NetworkData> {
	self.socket.set_read_timeout(None)?;
	let mut buf = [0; 300];
	let (amt, src) = self.socket.recv_from(&mut buf)?;
	let event: types::NetworkEvent = bincode::deserialize(&buf).unwrap();
	Ok(types::NetworkData {
	amt,
	src,
	event,
	})
	}

with:

    pub fn poll_event(&self) -> Result<types::NetworkData> {
        self.socket.set_read_timeout(None)?;
        let mut buf = [0; 300];
        loop {
            let (amt, src) = self.socket.recv_from(&mut buf)?;
            let result = bincode::deserialize(&buf);
            if let Ok(event) = result {
                break Ok(types::NetworkData {
                    amt,
                    src,
                    event,
                })
            }
        }
    }

and see whether the piano still panics when google home is online in the same network?

[andy5995]

Your patch works. Nice job.

btw, in case this info is helpful for debugging in the future, here's how to reproduce the crash (before your patch is applied) without a Google assistant:

• start piano-rs
• In another terminal, run 'echo -n "hello world" | nc -u -v -q20 9999'

(see nc/netcat or netcat on Wikipedia)

Where IP is an IP that piano-rs is listening on. I tested using the IP of my wlan interface.

Before the patch, I used iptraf-ng and saw that Google was indeed shooting packets to port 9999. I don't know why your earlier suggestion of using --receiver-address=127.0.0.1:6347 didn't work for me (maybe I used 0.0.0.0 instead of 127.0.0.1).

G appears to be broadcasting to these ports many times within 60 seconds, repeatedly: 9999, 10101, and 5353

[ritiek]

Your patch works. Nice job.

Good to know! I'll push it to master.

I don't know why your earlier suggestion of using --receiver-address=127.0.0.1:6347 didn't work for me (maybe I used 0.0.0.0 instead of 127.0.0.1).

Yep. That should've worked with 0.0.0.0 too as long no data is being received on that port. No idea why it didn't. Anyway, thanks for providing information on how to debug this, it's gonna be useful in future!