Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

run command with --device flag gets stuck #326

Closed
paulyoung opened this issue Apr 25, 2024 · 46 comments · Fixed by #358
Closed

run command with --device flag gets stuck #326

paulyoung opened this issue Apr 25, 2024 · 46 comments · Fixed by #358
Labels
bug Something isn't working cargo About cargo or cargo-playdate macOs usb

Comments

@paulyoung
Copy link
Contributor

As discussed in #314 (comment)

When I attempt to use cargo playdate run --device I can't get past the device showing "sharing DATA segment as USB drive" and "Eject disk to reboot".

My terminal says Running hello-world on a device and eventually exits but the device stays the same.

If I inspect the Games directory on the device while it's still mounted, the game isn't there. If I manually eject the device and then look for the game on it, it isn't there either.

@paulyoung
Copy link
Contributor Author

Also, using sudo doesn't make any difference.

@boozook boozook added bug Something isn't working cargo About cargo or cargo-playdate labels Apr 25, 2024
@boozook
Copy link
Owner

boozook commented Apr 25, 2024

If I inspect the Games directory on the device while it's still mounted, the game isn't there. If I manually eject the device and then look for the game on it, it isn't there either.

using sudo doesn't make any difference.

That is super strange. Then I suppose two options what's happening:

  1. The program can't determine device in the new state (mounted drive) after OS automatically mounted it;
  2. Or maybe OS didn't mounted your device as drive, so that is bigger problem then 1.

I'm not sure how works isolation in nix. Is it containerisation? If so, it could be that case when OS successfully mounted drive, but container didn't get it at all. 🤷🏻‍♂️


Could you try please following things from nix environment for debug purposes?

0. For each of following steps. Mount device (that's easy with pdtool that in the crate playdate-tool)

  1. pdtool list
  2. eject mount-point-path
  3. udisksctl unmount --no-user-interaction /dev/<device_id>, you can get the device ID using sudo fdisk -l command.
  4. Also could be cool to try udisksctl power-off --no-user-interaction /dev/<device_id>.

Also what happening if you try to mount device with command $PLAYDATE_SDK_PATH/bin/pdutil <device_serial_port> datadisk from your nix environment?

@paulyoung
Copy link
Contributor Author

Or maybe OS didn't mounted your device as drive, so that is bigger problem then 1.

The device is definitely mounted as a drive; I can explore it and need to eject the disk.

@paulyoung
Copy link
Contributor Author

I'm not sure how works isolation in nix. Is it containerisation?

It’s not, at least not in this case, and I’m using Nix on macOS FWIW.

In this instance I’m using it as a convenient way to set up a developer shell environment, which basically just puts various things on the PATH

@paulyoung
Copy link
Contributor Author

Could you try please following things from nix environment for debug purposes?

Will do, thanks!

@boozook
Copy link
Owner

boozook commented Apr 25, 2024

Wowowow! For macOs it's more than just strange!

Below I dive you commands that used for linux, not for macOS.

For macOS there is used diskutil eject /Volumes/<volume-name>, that is it.

@boozook
Copy link
Owner

boozook commented Apr 25, 2024

Oh, I probably know what's happening! That is await time shorter then your OS mounting the device, I suppose.
I have in plan to make wait time configurable.
Well, let's try! I'll make a patch with timeout configuration and we will see.

Anyway, please try commands pdtool list, pdtool mount, pdtool mount --wait (this one is important because there is same timout), pdtool unmount and pdtool unmount --wait.
FYI pdtool uses same code that used in cargo-playdate to interact with device.

@boozook
Copy link
Owner

boozook commented Apr 25, 2024

#328

Configuration env vars:

  • PD_MOUNT_TIMEOUT, default 1000 * 60 ms (= 60s)
  • PD_UNMOUNT_TIMEOUT, default 1000 * 60 ms (= 60s)

Values in milliseconds.

@boozook boozook moved this to 🏗 In progress in Playdate Development Apr 25, 2024
@paulyoung
Copy link
Contributor Author

pdtool list
Error:   × missing field `serial_num` at line 31 column 9

@paulyoung
Copy link
Contributor Author

paulyoung commented Apr 26, 2024

pdtool mount
[ERROR pdtool] Awaiting device timeout `XXXX-XXXXXXX(S)`.

This behaved the same as cargo playdate run --device but showed the error message at the end.

I just noticed that when both cargo playdate run --device and pdtool mount are running, the title of my terminal tab switches quickly between system_profiler and pdtool until the process exits.

Screen Shot 2024-04-25 at 8 06 52 PM

Screen Shot 2024-04-25 at 8 06 54 PM

Perhaps worth noting that the output above appears to be missing a digit. For example, if my device is ABC1_D2345678 then the output above is ABC1-D234567(S)

@paulyoung
Copy link
Contributor Author

pdtool mount --wait
[ERROR pdtool] Awaiting device timeout `XXXX-XXXXXXX(S)`.

This was the same as without the --wait flag.

@paulyoung
Copy link
Contributor Author

pdtool unmount
Error:   × missing field `serial_num` at line 31 column 9

@paulyoung
Copy link
Contributor Author

pdtool unmount --wait
Error:   × missing field `serial_num` at line 31 column 9

@boozook
Copy link
Owner

boozook commented Apr 26, 2024

Perhaps worth noting that the output above appears to be missing a digit. For example, if my device is ABC1_D2345678 then the output above is ABC1-D234567(S)

IMHO, there is no problem.

You can get real serial number from device this ways:

  1. Physically look at inner top surface of the hole where crank hiding
  2. pdtool send sn && pdtool read

Serial number format if [A-Z]{3}\d-[A-Z]\d{6}, so there are just six digits at the end. If you see seven, I suppose that last digit is 1 and it's a number of port (USB telmodem device can have multiple ports). Tell me if I was wrong, it could be interesting and point to fix.

Also, to make sure and rule it out as a suspect, I just add tests for it in #329.

@boozook
Copy link
Owner

boozook commented Apr 26, 2024

pdtool list
Error:   × missing field `serial_num` at line 31 column 9

Okay, now I know that you're on no latest macOS, probably on 12.x.x, because somewhere between 12 and 14 was "little improvement" in the output of system_profiler, so now it always returns SN if possible. Okay, if I right and that is it, I'll fix it.

@boozook
Copy link
Owner

boozook commented Apr 26, 2024

@paulyoung, may I ask you to connect your device and execute system_profiler -json SPUSBDataType and tell me the output? 🙄

@paulyoung
Copy link
Contributor Author

If you see seven, I suppose that last digit is 1 and it's a number of port (USB telmodem device can have multiple ports)

That appears to be the case, sorry for the confusion.

@paulyoung
Copy link
Contributor Author

Okay, now I know that you're on no latest macOS, probably on 12.x.x, because somewhere between 12 and 14 was "little improvement" in the output of system_profiler, so now it always returns SN if possible. Okay, if I right and that is it, I'll fix it.

I've been putting off upgrading just because I didn't want to deal with any churn that might come with it 😄

I'm on 12.2.1

@paulyoung
Copy link
Contributor Author

paulyoung commented Apr 27, 2024

I omitted a lot of fields for brevity and changed the names of things between angle brackets for privacy and security. I also redacted the serial number.

{
  "SPUSBDataType" : [
    {
      "_items" : [
        {
          "_items" : [
            {
              "_name" : "USB3.1 Hub             "
            }
          ],
          "_name" : "USB3.0 Hub"
        },
        {
          "_items" : [
            {
              "_name" : "<kvm hub>"
            },
            {
              "_items" : [
                {
                  "_name" : "<keyboard 1>"
                },
                {
                  "_name" : "<keyboard 2>"
                },
                {
                  "_name" : "<trackpad>"
                }
              ],
              "_name" : "USB2.0 Hub             "
            }
          ],
          "_name" : "USB2.0 Hub"
        }
      ],
      "_name" : "USB31Bus"
    },
    {
      "_name" : "USB31Bus"
    },
    {
      "_name" : "USB31Bus"
    },
    {
      "_items" : [
        {
          "_items" : [
            {
              "_name" : "<webcam>"
            }
          ],
          "_name" : "hub_device"
        },
        {
          "_name" : "Playdate",
          "bcd_device" : "2.00",
          "bus_power" : "500",
          "bus_power_used" : "100",
          "device_speed" : "full_speed",
          "extra_current_used" : "0",
          "location_id" : "0x03200000 / 6",
          "manufacturer" : "Panic Inc",
          "product_id" : "0x5740",
          "serial_num" : "XXXX-XXXXXXX",
          "vendor_id" : "0x1331"
        },
        {
          "_items" : [
            {
              "_name" : "USB Controls"
            }
          ],
          "_name" : "hub_device"
        }
      ],
      "_name" : "USB31Bus"
    }
  ]
}

@paulyoung
Copy link
Contributor Author

paulyoung commented Apr 27, 2024

I ran CARGO_PLAYDATE_LOG=trace cargo playdate run --device and looked at the code that calls system_profiler so have a better understanding of what that's trying to do now.

...
[DEBUG playdate_device::mount::methods] retries: 500 * 100ms ≈ 50s.
[TRACE polling] Poller::notify()
[TRACE polling::kqueue] notify: kqueue_fd=10
[TRACE polling::kqueue] new events: kqueue_fd=10, res=1
[TRACE async_io::reactor] process_timers: 0 ready wakers
[TRACE async_io::reactor] react: 0 ready wakers
[TRACE async_io::driver] main_loop: waiting on I/O
[TRACE async_io::reactor] process_timers: 0 ready wakers
[TRACE polling] Poller::wait(_, Some(99.978791ms))
[TRACE polling::kqueue] wait: kqueue_fd=10, timeout=Some(99.978791ms)
[TRACE polling::kqueue] new events: kqueue_fd=10, res=0
[TRACE async_io::reactor] process_timers: 1 ready wakers
[TRACE async_io::reactor] react: 1 ready wakers
[TRACE async_io::driver] main_loop: waiting on I/O
[TRACE async_io::reactor] process_timers: 0 ready wakers
[TRACE polling] Poller::wait(_, None)
[TRACE polling::kqueue] wait: kqueue_fd=10, timeout=None
[TRACE playdate_device::mount::methods] waiting mount point availability: XXXX-XXXXXXX, current: S, try: 1/500
[DEBUG playdate_device::mount::methods] ERROR: missing field `serial_num` at line 31 column 9
[DEBUG playdate_device::mount::methods] mount point still not found, waiting...
...

I think ERROR: missing field `serial_num` at line 31 column 9 must be the issue but it's there in the JSON and appears in the output after waiting mount point availability

@paulyoung
Copy link
Contributor Author

I did this locally and got a bit further.

diff --git a/support/device/src/mount/mac.rs b/support/device/src/mount/mac.rs
index 498e984..b2c5eb9 100644
--- a/support/device/src/mount/mac.rs
+++ b/support/device/src/mount/mac.rs
@@ -80,7 +80,7 @@ pub mod unmount {
 pub struct SpusbInfo<Fut>
        where Fut: Future<Output = Result<PathBuf, Error>> {
        pub name: String,
-       pub serial: String,
+       pub serial: Option<String>,
        pub volume: Fut,
 }
 
@@ -89,7 +89,9 @@ pub struct SpusbInfo<Fut>
 pub async fn volume_for<Info>(dev: Info) -> Result<Volume, Error>
        where Info: AsRef<nusb::DeviceInfo> {
        if let Some(sn) = dev.as_ref().serial_number() {
-               let res = spusb(move |info| info.serial_num == sn).map(|mut iter| iter.next().map(|info| info.volume));
+               let res = spusb(move |info| info.serial_num == Some(sn.to_string())).map(|mut iter| {
+                                                                                           iter.next().map(|info| info.volume)
+                                                                                   });
                match res {
                        Ok(None) => Err(Error::not_found()),
                        Ok(Some(fut)) => Ok(fut),
@@ -118,7 +120,7 @@ pub async fn volumes_for_map<I>(devs: I) -> Result<HashMap<Device, Option<Volume
        for info in spusb(|_| true)? {
                let i = devs.iter()
                            .enumerate()
-                           .find(|(_, (_, sn))| &info.serial == sn)
+                           .find(|(_, (_, sn))| info.serial == Some(sn.to_string()))
                            .map(|(i, _)| i);
 
                if let Some(i) = i {
@@ -149,7 +151,7 @@ pub fn volumes_for<'i, I: 'i>(
        spusb(|_| true).map(move |iter| {
                               iter.filter_map(move |info| {
                                           devs.iter()
-                                              .find(|(_, sn)| info.serial == *sn)
+                                              .find(|(_, sn)| info.serial == Some(sn.to_string()))
                                               .map(|(dev, _)| (info.volume, *dev))
                                   })
                       })
@@ -254,7 +256,7 @@ struct ControllerInfo {
 pub struct DeviceInfo {
        #[serde(rename = "_name")]
        pub name: String,
-       pub serial_num: String,
+       pub serial_num: Option<String>,
        pub vendor_id: String,
 
        #[serde(rename = "Media")]

It eventually fails with [ERROR playdate_device::run] Awaiting XXXX-XXXXXXX(S): filesystem not available at after 120 retries timeout.

@paulyoung
Copy link
Contributor Author

Before that I see:

[TRACE playdate_device::mount::volume] not mounted yet, create resolver fut
[DEBUG playdate_device::mount::methods] XXXX-XXXXXXX mounted, volume found: ''
[DEBUG playdate_device::mount::methods] retries: 120 * 500ms ≈ 60s.

@paulyoung
Copy link
Contributor Author

(although I would expect not to keep retrying if JSON decoding fails, perhaps that would be worth doing)

@paulyoung
Copy link
Contributor Author

I traced the value passed to Volume::from here and got a different result this time:

[TRACE playdate_device::mount::volume] existing, by name: /Volumes/PLAYDATE
[TRACE playdate_device::mount::volume] *************** "/Volumes/PLAYDATE"
[DEBUG playdate_device::mount::methods] XXXX-XXXXXXX mounted, volume found: '/Volumes/PLAYDATE'

.map(Volume::from)

The game installed and ran on my device. I reverted the change and it still works. I'm not sure what happened before that when I got volume found ''

@boozook
Copy link
Owner

boozook commented Apr 27, 2024

I'm not sure what happened before that when I got volume found '' (comment)

I know when mount point can be empty.

There is fn mount_point_for_partition that used as fallback to get mount-point for disk internal UUID. I case when drive already initialised in the driver and OS initialized auto-mount process (or not yet) it can be just empty!
I've forget about it! 🤦🏻‍♂️ Thank you!

How to reproduce it:

# requires jq
cargo run -p=playdate-tool mount && \
export PD_VOLUME_UUID=$(system_profiler -json SPUSBDataType | jq '.SPUSBDataType.[] | select(._items) | ._items.[].Media.[].volumes.[] | select(._name=="PLAYDATE") | .volume_uuid' -r) && \
diskutil info -plist $PD_VOLUME_UUID

There will be

<key>MountPoint</key>
<string></string>

Wait,
And then after OS finally completely mounted the drive we can repeat it without pdtool mount and get following:

<key>MountPoint</key>
<string>/Volumes/PLAYDATE</string>

I hope I fixed it in #330.

@boozook
Copy link
Owner

boozook commented Apr 27, 2024

I did this locally and got a bit further. (comment)

That's ok, I'm sure, because we are not interested in incomplete reports without serial-number at all. So to drop entire function is easier then continue parse, search item of interest, check is there sn existing, your know.

@paulyoung paulyoung reopened this May 1, 2024
@github-project-automation github-project-automation bot moved this from Done to Todo in Playdate Development May 1, 2024
@boozook boozook moved this from Todo to 🏗 In progress in Playdate Development May 1, 2024
@boozook
Copy link
Owner

boozook commented May 1, 2024

Could it be previously installed cargo-playdate?
Just to be sure, try this:

cargo run -p=cargo-playdate -- package -p=playdate-system --example=set-serial-message-callback --features=sys/lang-items,sys/entry-point --device

cargo run -p=playdate-tool -- run dev target/thumbv7em-none-eabihf/debug/playdate/playdate_system-set-serial-message-callback.pdx --no-read

You can update to latest from crates.io with cargo install cargo-playdate --force, you know, or from local - cargo install --path=./cargo.

boozook added a commit that referenced this issue May 1, 2024
@boozook
Copy link
Owner

boozook commented May 1, 2024

@paulyoung I've added debug print of response where error caused. Branch: dev/debug-326 (link). You can checkout and build, or take build from CI (see "Artifacts" there).

I'm a little bit out of ideas, I don't really understand why you're getting this error. 🤷🏻‍♂️

@paulyoung
Copy link
Contributor Author

I tried again from main and it works as expected. I'll try dev/debug-326 just to be sure.

@paulyoung
Copy link
Contributor Author

Works great here. Not sure what happened. Thanks again.

@github-project-automation github-project-automation bot moved this from 🏗 In progress to Done in Playdate Development May 2, 2024
@boozook
Copy link
Owner

boozook commented May 2, 2024

@paulyoung
That is strange. Don’t hesitate to reopen this issue if something happens again. Thank you so much!

@paulstraw
Copy link

I'm also hitting the issue originally described here. My env:

  • macOS 14.4.1, Apple Silicon
  • playdate 0.2.0 specified in Cargo.lock
  • rustc 1.80.0-nightly (faefc618c 2024-05-07)

@boozook
Copy link
Owner

boozook commented May 9, 2024

Hey @paulstraw 👋🏻
Sorry for this question, but are you using the latest cargo-playdate (v0.4) ?
Could you try pdtool mount --wait and ... unmount --wait, just as experiment?

@boozook boozook reopened this May 9, 2024
@github-project-automation github-project-automation bot moved this from Done to Todo in Playdate Development May 9, 2024
@paulyoung
Copy link
Contributor Author

I'm sure the last issue I posted about here was due to the wrong/old build of cargo-playdate hanging around in my Nix dev shell.

It happened again when I was working on the Lua API PR and had pulled in some changes from the main branch. I'm not yet sure why it happens when I do that but I was able to identify it and make sure I was using the correct build.

All of that to say, this issue remains fixed for me at the moment.

@paulstraw
Copy link

Thanks guys, appreciate the prompt and thorough responses.

» cargo-playdate --version
cargo 0.4.10

When running pdtool mount --wait, the connected Playdate enters data disk mode very quickly. My shell sits waiting for a minute or so, eventually timing out with [ERROR pdtool] Awaiting device timeout `PDU1-YMYSERIAL(S)`.. The Playdate is visible in Finder as expected during/after.

@boozook
Copy link
Owner

boozook commented May 10, 2024

@paulstraw I suppose its about changed format of system_profiler.

To get exactly what's wrong I recommend do two steps.

But first of all set RUST_LOG and CARGO_PLAYDATE_LOG env vars to "trace.

Well, first step is to mount device somehow (use pdutil, pdtool or by hand) and then run following command and show me the output (I need just structure with names of fields and to know that value is empty or not)

system_profiler -json SPUSBDataType

Second is similar, but imitate used fallback method to determine mount-point:

# requires jq
export PD_VOLUME_UUID=$(system_profiler -json SPUSBDataType | jq '.SPUSBDataType.[] | select(._items) | ._items.[].Media.[].volumes.[] | select(._name=="PLAYDATE") | .volume_uuid' -r) && \
diskutil info -plist $PD_VOLUME_UUID

(same as above)

This way we can understand whether the problem is in the output format or not.

@paulstraw
Copy link

» RUST_LOG=trace CARGO_PLAYDATE_LOG=trace system_profiler -json SPUSBDataType

A bunch of output removed for brevity/privacy:

{
  "SPUSBDataType" : [
    {
      "_items" : [
        {
          "_items" : [
            {
              "_name" : "Playdate",
              "bcd_device" : "2.00",
              "bus_power" : "500",
              "bus_power_used" : "100",
              "device_speed" : "full_speed",
              "extra_current_used" : "0",
              "location_id" : "0x05310000 / 24",
              "manufacturer" : "Panic Inc",
              "Media" : [
                {
                  "_name" : "Playdate",
                  "bsd_name" : "disk24",
                  "Logical Unit" : 0,
                  "partition_map_type" : "master_boot_record_partition_map_type",
                  "removable_media" : "yes",
                  "size" : "3.66 GB",
                  "size_in_bytes" : 3662675968,
                  "smart_status" : "Verified",
                  "USB Interface" : 0,
                  "volumes" : [
                    {
                      "_name" : "PLAYDATE",
                      "bsd_name" : "disk24s1",
                      "file_system" : "MS-DOS FAT32",
                      "free_space" : "2.13 GB",
                      "free_space_in_bytes" : 2133676032,
                      "iocontent" : "Windows_FAT_32",
                      "mount_point" : "/Volumes/PLAYDATE",
                      "size" : "3.66 GB",
                      "size_in_bytes" : 3662675456,
                      "volume_uuid" : "83B4406D-",
                      "writable" : "yes"
                    }
                  ]
                }
              ],
              "product_id" : "0x5741",
              "serial_num" : "PDU1-Y0xxxxx",
              "vendor_id" : "0x1331"
            }
          ],
          "_name" : "4-Port USB 2.0 Hub",
          "bcd_device" : "1.36",
          "bus_power" : "500",
          "bus_power_used" : "0",
          "device_speed" : "high_speed",
          "extra_current_used" : "0",
          "location_id" : "0x05300000 / 3",
          "manufacturer" : "Generic",
          "product_id" : "0x5411",
          "vendor_id" : "0x0bda  (Realtek Semiconductor Corp.)"
        },
      ],
      "_name" : "USB31Bus",
      "host_controller" : "AppleASMediaUSBXHCI",
      "pci_device" : "0x1242 ",
      "pci_revision" : "0x0000 ",
      "pci_vendor" : "0x1b21 "
    },
  ]
}%

Running the second command errors with jq: error (at <stdin>:313): Cannot iterate over null (null). This adjusted command gives the expected UUID: system_profiler -json SPUSBDataType | jq '.SPUSBDataType[] | ._items[]? | ._items[]?.Media[]?.volumes[]? | select(._name=="PLAYDATE") | .volume_uuid' -r

@boozook
Copy link
Owner

boozook commented May 12, 2024

@paulstraw

{
  "SPUSBDataType" : [
    {
      "_items" : [
        {
          "_items" : [
            {

Are you sure that there was two _items?

Ah okay I see, there is 4-Port USB 2.0 Hub 😬

PR with fix for this: #358,
Artefacts you might want try before merge are there.

@boozook boozook linked a pull request May 12, 2024 that will close this issue
@boozook boozook moved this from Todo to 🏗 In progress in Playdate Development May 12, 2024
@paulstraw
Copy link

Ah, yes I should have mentioned that. I have a bunch of USB devices/hubs connected to my machine, and previously the Playdate was connected two hubs deep.

Trying the new build, I see the expected behavior and trace/debug output for pdtool mount --wait and pdtool unmount --wait. I confirmed this new build works with the PD connected directly, 1, 2, and 3 hubs deep. Thanks very much for getting this figured out and fixed so quickly!

boozook added a commit that referenced this issue May 12, 2024
* Support devices connected via USB-hub on macOs (fixes #326)

* Bump bins, update deps
@github-project-automation github-project-automation bot moved this from 🏗 In progress to Done in Playdate Development May 12, 2024
@boozook
Copy link
Owner

boozook commented May 12, 2024

Thank you. Done, merged, published.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working cargo About cargo or cargo-playdate macOs usb
Projects
Archived in project
Development

Successfully merging a pull request may close this issue.

3 participants