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

shell command not finishing before next command is executed using await #58

Open
rsc-rchristensen opened this issue Dec 9, 2016 · 17 comments

Comments

@rsc-rchristensen
Copy link

A little background, I am using your library to push a firmware update file to a custom android device. In order for the device to detect the update file, it has to be in a particular block device at a particular mount point. If I execute these shell commands in order, the push goes through, the file ends up where it is supposed to be, and the device picks up the firmware no problem. When I execute the same commands using your library, the commands execute properly, however the file ends up in the mount target folder and not the actual mounted device.

Working adb commands in ubuntu terminal:

adb shell mount /dev/block/mmcblk1p5 /mntpnt
adb push tmpUpdate.zip /mntpnt
adb shell mv /mntpnt/tmpUpdate.zip /mntpnt/update.zip
adb umount /mntpnt

When I do the same commands using your library (using Electron/babel await if that makes a difference):

 await client.shell(device.id, 'mount -t vfat /dev/block/mmcblk1p5 /mntpnt');
 await client.shell(device.id, 'sync');
 const pushFile = await client.push(device.id, updateFilePath, '/mntpnt/tmpFirmware.zip');
 pushFile.on('progress', (stats) => {
   store.dispatch(DEVICE_FIRMWARE_UPDATE_PROGRESS(device.id, { status: 'copyingFirmwareFile', progress: (stats.bytesTransferred / updateFiles.get(updateFile.fileName).get('total')) * 100 }));
 });
 pushFile.on('end', async () => {
   store.dispatch(DEVICE_FIRMWARE_UPDATE_PROGRESS(device.id, { status: 'finishedCopyingFirmwareFile' }));
   await client.shell(device.id, 'sync');
   await client.shell(device.id, 'mv /mntpnt/tmpFirmware.zip /mntpnt/update.zip');
   await client.shell(device.id, 'sync');
   await client.shell(device.id, 'umount /mntpnt');
   await client.shell(device.id, 'sync');
   store.dispatch(DEVICE_FIRMWARE_UPDATE_PROGRESS(device.id, { status: 'waitingForReboot' }));
 });

When I run the commands using adbkit, the device doesn't detect the update, so I shell in, I can see the file in the /mntpnt directory, however the block device is not mounted. However, if I shell in during the transfer, I can see in mount that the device is mounted. Once I mount the block device manually, the files disappear (due to the mount location changing for the dir), and then once I unmount again, the files are back. Any idea or direction would be greatly appreciated.

Notes:
shell sync commands added based on previous comments, does not work with or without although does seem to improve the reliability of the mv command (to rename the file) when sync is called after each shell command

I have also added console logs to the shell commands and the output seems to be what I expect, it just seems like the client.push is what is not performing the way I expect it to.

@sorccu
Copy link
Member

sorccu commented Dec 9, 2016 via email

@rsc-rchristensen
Copy link
Author

mounting the block device then using this command:

adb push update-bigupgrade-161129-signed.zip /mntpnt/tmpFirmware.zip

results in the file being where it is supposed to be and picked up by our device

@rsc-rchristensen
Copy link
Author

Interesting note, I modified the client.push command to just be the mount point (excluding filename) and I got these errors (many more, truncated since they are all the same). the interesting thing though is, the update file was picked up by my device unexpectedly and the update was performed. That means the file copy was successful and placed the file in the correct location. Due to the input filename, the rename could not have succeeded, but the umount would have had to since if the block device is mounted, the update watcher service cannot check for an update file.

Unhandled rejection Error: This socket has been ended by the other party
    at Socket.writeAfterFIN [as write] (net.js:286:12)
    at Connection.write (/home/russell/Documents/firmware_updater/node_modules/adbkit/lib/adb/connection.js:70:17)
    at Sync._sendCommandWithLength (/home/russell/Documents/firmware_updater/node_modules/adbkit/lib/adb/sync.js:307:28)
    at writeNext (/home/russell/Documents/firmware_updater/node_modules/adbkit/lib/adb/sync.js:180:19)
    at runCallback (timers.js:574:20)
    at tryOnImmediate (timers.js:554:5)
    at processImmediate [as _immediateCallback] (timers.js:533:5)
From previous event:
    at ReadStream.readableListener (/home/russell/Documents/firmware_updater/node_modules/adbkit/lib/adb/sync.js:192:25)
    at emitNone (events.js:86:13)
    at ReadStream.emit (events.js:185:7)
    at emitReadable_ (_stream_readable.js:432:10)
    at emitReadable (_stream_readable.js:426:7)
    at readableAddChunk (_stream_readable.js:187:13)
    at ReadStream.Readable.push (_stream_readable.js:134:10)
    at onread (fs.js:1994:12)
    at FSReqWrap.wrapper [as oncomplete] (fs.js:681:17)
Unhandled rejection Error: This socket has been ended by the other party
    at Socket.writeAfterFIN [as write] (net.js:286:12)
    at Connection.write (/home/russell/Documents/firmware_updater/node_modules/adbkit/lib/adb/connection.js:70:17)
    at Sync._sendCommandWithLength (/home/russell/Documents/firmware_updater/node_modules/adbkit/lib/adb/sync.js:307:28)
    at writeNext (/home/russell/Documents/firmware_updater/node_modules/adbkit/lib/adb/sync.js:180:19)
    at runCallback (timers.js:574:20)
    at tryOnImmediate (timers.js:554:5)
    at processImmediate [as _immediateCallback] (timers.js:533:5)
From previous event:
    at ReadStream.readableListener (/home/russell/Documents/firmware_updater/node_modules/adbkit/lib/adb/sync.js:192:25)
    at emitNone (events.js:86:13)
    at ReadStream.emit (events.js:185:7)
    at emitReadable_ (_stream_readable.js:432:10)
    at emitReadable (_stream_readable.js:426:7)
    at readableAddChunk (_stream_readable.js:187:13)
    at ReadStream.Readable.push (_stream_readable.js:134:10)
    at onread (fs.js:1994:12)
    at FSReqWrap.wrapper [as oncomplete] (fs.js:681:17)
Unhandled rejection Error: This socket has been ended by the other party
    at Socket.writeAfterFIN [as write] (net.js:286:12)
    at Connection.write (/home/russell/Documents/firmware_updater/node_modules/adbkit/lib/adb/connection.js:70:17)
    at Sync._sendCommandWithLength (/home/russell/Documents/firmware_updater/node_modules/adbkit/lib/adb/sync.js:307:28)
    at /home/russell/Documents/firmware_updater/node_modules/adbkit/lib/adb/sync.js:160:19
    at runCallback (timers.js:574:20)
    at tryOnImmediate (timers.js:554:5)
    at processImmediate [as _immediateCallback] (timers.js:533:5)
From previous event:
    at ReadStream.endListener (/home/russell/Documents/firmware_updater/node_modules/adbkit/lib/adb/sync.js:159:25)
    at emitNone (events.js:91:20)
    at ReadStream.emit (events.js:185:7)
    at endReadableNT (_stream_readable.js:974:12)
    at _combinedTickCallback (internal/process/next_tick.js:74:11)
    at process._tickCallback (internal/process/next_tick.js:98:9)

@sorccu
Copy link
Member

sorccu commented Dec 9, 2016 via email

@rsc-rchristensen
Copy link
Author

here you are, included two files, one where I pushed to the plain directory, the other where I pushed to the directory after I had run the mount command.

push_pcap.zip

@sorccu
Copy link
Member

sorccu commented Dec 9, 2016

There doesn't seem to be any difference. Could you do two more caps:

One with your adb commands, including mount, the way it's supposed to be (but with a small test file to reduce noise)

And another with the exact same thing using adbkit. You can get rid of the syncs as well, just keep it as similar as possible.

@sorccu
Copy link
Member

sorccu commented Dec 9, 2016

Both should include the mount command.

@rsc-rchristensen
Copy link
Author

Ok, took me a bit of playing but I managed to get these files. wireshark_test_terminal is me manually doing the commands, wireshark_test_app is doing the same commands (mostly) from the app using the library. One thing I noticed is in the app one, it calls the commands for mv file then umount but then a few packets later gets the response that it can't mv the file because it doesn't exist. This makes me think that there is a race condition and maybe the adb push is happening before the volume mount is finished. The way I have this set up, are those commands supposed to happen one after another? note in the terminal version, I did not perform the move due to not wanting the system to pick up a file that isn't an update and think it is an update.

i did confirm after both of these procedures that the same thing is happening, when i use the sdk, the file does not get put on the block device, when I do it from ubuntu terminal manually the file goes where it is supposed to.

wireshark_test.zip

@sorccu
Copy link
Member

sorccu commented Dec 9, 2016

I haven't had time to check it out yet but there are two things. If it's a timing issue, I would recommend running a script that issues all the commands at once instead of running them manually (you'll never get the timing issue that way). Also, every adb invocation begins with an adb version check that takes a bit of time, so it may be less prone to appear there. Perhaps just run several commands in one adb shell and see if you can repro the timing issue that way.

Also, try adding await Promise.delay(1000) after the mount and report back with whether it works or not.

@rsc-rchristensen
Copy link
Author

Sorry about the delayed response, I added a delay of 1 second after the mount and it did indeed resolve my issue with the file copy to the correct block device. It seems that when you run a shell command, the promise returns before the command has fully finished executing. Is this by design or could this be considered a bug? If it is intended, then we can consider the issue closed and I will find another way to poll that the task has finished to ensure consistency.

@sorccu
Copy link
Member

sorccu commented Dec 16, 2016

I think it's a bug but perhaps you try to run the whole thing as one adb shell command (without adbkit) and see if the timing issue still occurs? I'm wondering if it's just that the mount needs a bit of time to think in any case. When you run the commands by hand, you're introducing a delay between each command, which might make it work even if the timing issue is always present. Even if you run several adb shell commands, it'll have much more overhead than adbkit, and may therefore work as well. So perhaps create a script with the commands, upload it to the device and then run it. If that works then it's a bug in adbkit.

@rsc-rchristensen
Copy link
Author

I guess the problem is I have to push a file in between the commands so it goes:

adb shell mount
adb push file
adb shell rename file (mv oldFilename newFilename)
adb shell umount

@sorccu
Copy link
Member

sorccu commented Dec 16, 2016

Ok I think I just realized what's wrong. You're not consuming the output of the shell command. That would keep it alive. If you're not interested in the output, you can do await client.shell('echo 1').then(adbkit.util.readAll) to consume it. Otherwise the output goes nowhere and it forever waits for someone to read it. Can you try that?

@rsc-rchristensen
Copy link
Author

in this case I'm not using bluebird, so I worked my code around to do this:

console.log('mounting block device');
      await client.shell(device.id, 'mount -t vfat /dev/block/mmcblk1p5 /tek2', async (err, result) => {
        console.log(`mount complete: err: ${err}\nresult: ${result}`);
        console.log('reading result');
        const resultString = await adb.util.readAll(result);
        console.log(`read result: ${resultString}`);
        console.log('starting push of file');
        const pushFile = await client.push(device.id, updateFilePath, '/tek2/tmpFirmware.zip');
        pushFile.on('progress', (stats) => {
          console.log('push file progress');
          store.dispatch(DEVICE_FIRMWARE_UPDATE_PROGRESS(device.id, { status: 'copyingFirmwareFile', progress: (stats.bytesTransferred / updateFiles.get(updateFile.fileName).get('total')) * 100 }));
        });
        pushFile.on('end', async () => {
          console.log('push file end');
          store.dispatch(DEVICE_FIRMWARE_UPDATE_PROGRESS(device.id, { status: 'finishedCopyingFirmwareFile' }));
          console.log('starting rename');
          await client.shell(device.id, 'mv /tek2/tmpFirmware.zip /tek2/update.zip');
          console.log('finished rename, unmounting');
          await client.shell(device.id, 'umount /tek2');
          console.log('finished unmount, waiting for reboot');
          store.dispatch(DEVICE_FIRMWARE_UPDATE_PROGRESS(device.id, { status: 'waitingForReboot' }));
        });

      });

this results in the correct actions, but there is at least a 20-30 second delay from the time of the mount return to the time that the file actually starts copying. any idea what could be causing that delay? If I just leave the 1 second delay in there, it works fine and goes fairly quick, although with another issue I was going to type up here in a little bit.

@rsc-rchristensen rsc-rchristensen changed the title client.push file ends up in wrong directory (mount) shell command not finishing before next command is executed using await Dec 16, 2016
@sorccu
Copy link
Member

sorccu commented Dec 16, 2016 via email

@rsc-rchristensen
Copy link
Author

rsc-rchristensen commented Dec 16, 2016 via email

@sorccu
Copy link
Member

sorccu commented Dec 16, 2016

No reason to close it, but please remember to update when you can - so many leave ghost tickets laying around :(

I don't really have any experience with mounting inside devices so getting this figured out would be great.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants