search

Azelphur / PokemonGo-CalcyIV-Renamer

Uses adb to send fake tap events to your phone, alongside Calcy IV to automatically rename all your pokemon.
GNU General Public License v3.0
77 stars 32 forks source link

getting a debug error on run #7

Closed AVellucci closed 5 years ago

AVellucci commented 5 years ago

When running the ivcheck.py in python 3.7 on MacOS I get the following output spamming the terminal

2018-09-21 17:09:09,752 - PokemonGo - DEBUG - Received logcat line: b''
2018-09-21 17:09:09,753 - PokemonGo - DEBUG - Received logcat line: b''
2018-09-21 17:09:09,754 - PokemonGo - DEBUG - Received logcat line: b''
2018-09-21 17:09:09,754 - PokemonGo - DEBUG - Received logcat line: b''
2018-09-21 17:09:09,755 - PokemonGo - DEBUG - Received logcat line: b''
2018-09-21 17:09:09,755 - PokemonGo - DEBUG - Received logcat line: b''
2018-09-21 17:09:09,755 - PokemonGo - DEBUG - Received logcat line: b''
2018-09-21 17:09:09,756 - PokemonGo - DEBUG - Received logcat line: b''
2018-09-21 17:09:09,756 - PokemonGo - DEBUG - Received logcat line: b''
2018-09-21 17:09:09,756 - PokemonGo - DEBUG - Received logcat line: b''
2018-09-21 17:09:09,756 - PokemonGo - DEBUG - Received logcat line: b''
2018-09-21 17:09:09,756 - PokemonGo - DEBUG - Received logcat line: b''
2018-09-21 17:09:09,757 - PokemonGo - DEBUG - Received logcat line: b''
2018-09-21 17:09:09,757 - PokemonGo - DEBUG - Received logcat line: b''

Am I doing something wrong? shoudl I be running this with sudo?

Azelphur commented 5 years ago

Give it another try, I think I've addressed this in the latest commit. Let me know if it solves it for you :)

It seems some phones don't support logcat on a specific process, so I've stopped pid filtering on logcat for now.

AVellucci commented 5 years ago

using the f8c2bcc commit it doesn't seem to solve my issue although you can see that is does kind of hold for a second before outputting the logs but I think that due to my wait times being 1

2018-09-22 23:18:49,629 - PokemonGo - DEBUG - Running ['adb', 'devices']
2018-09-22 23:18:49,637 - PokemonGo - DEBUG - Return code 0
2018-09-22 23:18:49,638 - PokemonGo - DEBUG - Starting logcat ['adb', '-s', 'REDACTED', 'logcat', '-T', '1']
2018-09-22 23:18:50,150 - PokemonGo - DEBUG - Running ['adb', '-s', 'REDACTED', 'shell', 'am broadcast -a tesmath.calcy.ACTION_ANALYZE_SCREEN -n tesmath.calcy/.IntentReceiver']
2018-09-22 23:18:52,321 - PokemonGo - DEBUG - Return code 0
2018-09-22 23:19:10,829 - PokemonGo - DEBUG - Received logcat line: b'--------- beginning of main\r\n'
2018-09-22 23:19:10,830 - PokemonGo - DEBUG - Received logcat line: b'D/libEGL  (14512): glBindBuffer(0x8893, 0);\r\n'
2018-09-22 23:19:10,834 - PokemonGo - DEBUG - Received logcat line: b'D/libEGL  (14512): glBindBuffer(0x8f37, 568);\r\n'
2018-09-22 23:19:10,835 - PokemonGo - DEBUG - Received logcat line: b'D/libEGL  (14512): glMapBufferRange(0x8f37, 0, 480, 0x0000003a);\r\n'
2018-09-22 23:19:10,835 - PokemonGo - DEBUG - Received logcat line: b'D/libEGL  (14512): glBindBuffer(0x8f37, 283);\r\n'
2018-09-22 23:19:10,835 - PokemonGo - DEBUG - Received logcat line: b'D/libEGL  (14512): glMapBufferRange(0x8f37, 0, 24, 0x0000003a);\r\n'
2018-09-22 23:19:10,835 - PokemonGo - DEBUG - Received logcat line: b'D/libEGL  (14512): glBindBuffer(0x8f37, 739);\r\n'
2018-09-22 23:19:10,835 - PokemonGo - DEBUG - Received logcat line: b'D/libEGL  (14512): glMapBufferRange(0x8f37, 0, 150920, 0x0000003a);\r\n'
2018-09-22 23:19:10,835 - PokemonGo - DEBUG - Received logcat line: b'D/libEGL  (14512): glBindBuffer(0x8f37, 341);\r\n'
2018-09-22 23:19:10,835 - PokemonGo - DEBUG - Received logcat line: b'D/libEGL  (14512): glMapBufferRange(0x8f37, 0, 314760, 0x0000003a);\r\n'
2018-09-22 23:19:10,836 - PokemonGo - DEBUG - Received logcat line: b'D/libEGL  (14512): glBindBuffer(0x8f37, 433);\r\n'
2018-09-22 23:19:10,836 - PokemonGo - DEBUG - Received logcat line: b'D/libEGL  (14512): glMapBufferRange(0x8f37, 0, 54880, 0x0000003a);\r\n'
2018-09-22 23:19:10,836 - PokemonGo - DEBUG - Received logcat line: b'D/libEGL  (14512): glBindBuffer(0x8f37, 284);\r\n'
2018-09-22 23:19:10,836 - PokemonGo - DEBUG - Received logcat line: b'D/libEGL  (14512): glMapBufferRange(0x8f37, 0, 1680, 0x0000003a);\r\n'
2018-09-22 23:19:10,836 - PokemonGo - DEBUG - Received logcat line: b'D/libEGL  (14512): glBindBuffer(0x8f37, 642);\r\n'
2018-09-22 23:19:10,836 - PokemonGo - DEBUG - Received logcat line: b'D/libEGL  (14512): glMapBufferRange(0x8f37, 0, 4080, 0x0000003a);\r\n'
2018-09-22 23:19:10,836 - PokemonGo - DEBUG - Received logcat line: b'D/libEGL  (14512): glBindBuffer(0x8f37, 323);\r\n'
2018-09-22 23:19:10,837 - PokemonGo - DEBUG - Received logcat line: b'D/libEGL  (14512): glMapBufferRange(0x8f37, 0, 4080, 0x0000003a);\r\n'
2018-09-22 23:19:10,837 - PokemonGo - DEBUG - Received logcat line: b'D/libEGL  (14512): glBindBuffer(0x8f37, 568);\r\n'
2018-09-22 23:19:10,837 - PokemonGo - DEBUG - Received logcat line: b'D/libEGL  (14512): glFlushMappedBufferRange(0x8f37, 0, 480);\r\n'
2018-09-22 23:19:10,837 - PokemonGo - DEBUG - Received logcat line: b'D/libEGL  (14512): glUnmapBuffer(0x8f37);\r\n'
2018-09-22 23:19:10,837 - PokemonGo - DEBUG - Received logcat line: b'D/libEGL  (14512): glBindBuffer(0x8f37, 283);\r\n'
2018-09-22 23:19:10,838 - PokemonGo - DEBUG - Received logcat line: b'D/libEGL  (14512): glFlushMappedBufferRange(0x8f37, 0, 24);\r\n'
2018-09-22 23:19:10,838 - PokemonGo - DEBUG - Received logcat line: b'D/libEGL  (14512): glUnmapBuffer(0x8f37);\r\n'
2018-09-22 23:19:10,838 - PokemonGo - DEBUG - Received logcat line: b'D/libEGL  (14512): glBindBuffer(0x8f37, 739);\r\n'

This goes on infinitely, and it looks like it's just printing the logcat to the terminal, although I could be wrong

Azelphur commented 5 years ago

Hi, that's what it should be doing, printing the log lines (although the latest version filters it down a little more).

The script watches logcat for calcy iv messages to confirm that it worked.

Can you give the latest version a try, and paste the full log?

AVellucci commented 5 years ago

in this latest build 878010c it just sort of hangs at return code 0:

2018-10-01 13:32:51,600 - PokemonGo - DEBUG - Running ['adb', 'devices']
2018-10-01 13:32:51,607 - PokemonGo - DEBUG - Return code 0
2018-10-01 13:32:51,608 - PokemonGo - DEBUG - Running ['adb', '-s', '2WMDU16A29001779', 'shell', 'pidof', '-s', 'tesmath.calcy']
2018-10-01 13:32:51,650 - PokemonGo - DEBUG - Return code 0
2018-10-01 13:32:51,650 - PokemonGo - DEBUG - Running pidof calcy got code 0: b'1\r\n'
2018-10-01 13:32:51,651 - PokemonGo - DEBUG - Starting logcat ['adb', '-s', '2WMDU16A29001779', 'logcat', '-T', '1']
2018-10-01 13:32:52,161 - PokemonGo - DEBUG - Running ['adb', '-s', '2WMDU16A29001779', 'shell', 'am broadcast -a tesmath.calcy.ACTION_ANALYZE_SCREEN -n tesmath.calcy/.IntentReceiver']
2018-10-01 13:32:53,430 - PokemonGo - DEBUG - Return code 0
^C^CTraceback (most recent call last):
  File "/Users/Aldo/.pyenv/versions/3.7.0/lib/python3.7/asyncio/runners.py", line 43, in run
    return loop.run_until_complete(main)
  File "/Users/Aldo/.pyenv/versions/3.7.0/lib/python3.7/asyncio/base_events.py", line 555, in run_until_complete
    self.run_forever()
  File "/Users/Aldo/.pyenv/versions/3.7.0/lib/python3.7/asyncio/base_events.py", line 523, in run_forever
    self._run_once()
  File "/Users/Aldo/.pyenv/versions/3.7.0/lib/python3.7/asyncio/base_events.py", line 1758, in _run_once
    handle._run()
  File "/Users/Aldo/.pyenv/versions/3.7.0/lib/python3.7/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
  File "/Users/Aldo/.pyenv/versions/3.7.0/lib/python3.7/asyncio/subprocess.py", line 71, in pipe_data_received
    reader.feed_data(data)
  File "/Users/Aldo/.pyenv/versions/3.7.0/lib/python3.7/asyncio/streams.py", line 434, in feed_data
    self._wakeup_waiter()
  File "/Users/Aldo/.pyenv/versions/3.7.0/lib/python3.7/asyncio/streams.py", line 408, in _wakeup_waiter
    waiter.set_result(None)
  File "/Users/Aldo/.pyenv/versions/3.7.0/lib/python3.7/asyncio/base_events.py", line 676, in call_soon
    handle = self._call_soon(callback, args, context)
  File "/Users/Aldo/.pyenv/versions/3.7.0/lib/python3.7/asyncio/base_events.py", line 692, in _call_soon
    handle = events.Handle(callback, args, self, context)
  File "/Users/Aldo/.pyenv/versions/3.7.0/lib/python3.7/asyncio/events.py", line 46, in __init__
    self._cancelled = False
KeyboardInterrupt

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "./ivcheck.py", line 117, in <module>
    asyncio.run(Main(args).start())
  File "/Users/Aldo/.pyenv/versions/3.7.0/lib/python3.7/asyncio/runners.py", line 46, in run
    _cancel_all_tasks(loop)
  File "/Users/Aldo/.pyenv/versions/3.7.0/lib/python3.7/asyncio/runners.py", line 62, in _cancel_all_tasks
    tasks.gather(*to_cancel, loop=loop, return_exceptions=True))
  File "/Users/Aldo/.pyenv/versions/3.7.0/lib/python3.7/asyncio/base_events.py", line 555, in run_until_complete
    self.run_forever()
  File "/Users/Aldo/.pyenv/versions/3.7.0/lib/python3.7/asyncio/base_events.py", line 523, in run_forever
    self._run_once()
  File "/Users/Aldo/.pyenv/versions/3.7.0/lib/python3.7/asyncio/base_events.py", line 1722, in _run_once
    event_list = self._selector.select(timeout)
  File "/Users/Aldo/.pyenv/versions/3.7.0/lib/python3.7/selectors.py", line 558, in select
    kev_list = self._selector.control(None, max_ev, timeout)
KeyboardInterrupt

I'm not sure what may be stopping it, I should note that on run it does trigger the calcy scan and I see the overlay displayed but once that happens nothing else occurs. I've left nothing out of this log just so that it's unfiltered. you can see where I hit CTRL+C twice and the error output received when done so.

Azelphur commented 5 years ago

Would you mind changing the 0.5 to 0.1 on this line? https://github.com/Azelphur/PokemonGo-CalcyIV-Renamer/blob/master/pokemonlib.py#L75

See if that resolves the issue for you?

Azelphur commented 5 years ago

Actually, above won't solve it, although I think I've found your problem, it looks like adb shell pidof -s tesmath.calcy is returning 1 - it shouldn't be though, can you confirm that running that command gives you 1 back?

AVellucci commented 5 years ago

running that command does in fact give me 1

Azelphur commented 5 years ago

that's really odd, can you run adb logcat and press the Calcy IV button, and paste the Calcy IV lines here?

The script works by filtering logcat lines by calcy IVs pid, which should not be 1.

AVellucci commented 5 years ago

I did try this adb shell ps | grep tesmath.calcy | awk '{ print $2 }' and with that I'm able to return the PID correctly. Could be that my phone just doesn't like pidof?

as for the Calcy Logcat, here is what I get from it, hopefully I didn't cut out a portion of it:


I/DisplayManagerService( 1160): Display device removed: DisplayDeviceInfo{"screen-mirror": uniqueId="virtual:tesmath.calcy,10093,screen-mirror,0", 640 x 1138, modeId 454, defaultModeId 454, supportedModes [{id=454, width=640, height=1138, fps=60.0}], density 252, 252.0 x 252.0 dpi, appVsyncOff 0, presDeadline 16666666, touch NONE, rotation 0, type VIRTUAL, state ON, owner tesmath.calcy (uid 10093), FLAG_PRIVATE, FLAG_PRESENTATION}
E/BufferQueueProducer(25305): [ImageReader-640x1138f1m2-25305-14] dequeueBuffer: BufferQueue has been abandoned
D/cmb     (25305): ********* Analyzing 3 screenshots ***********
D/cmb     (25305): isMonsterScreen: White box confidence: 0.96
D/cmb     (25305): isMonsterScreen: HP-Bar confidence: 1.00
D/cmb     (25305): Detected monster screen
D/cmb     (25305): OCR-Dust #0: 200
D/cmb     (25305): Search level: 1.0 (1.000, trainer level: 17)
D/cmb     (25305): OCR-CandyName (scaled): CHARMANDER CANDY
D/cmb     (25305): OCR-CandyName after processing: CHARMANDER
D/cmb     (25305): Found candy name: Charmander
D/cmb     (25305): OCR-EvoCost #0: 2
D/cmb     (25305): OCR-HP: 0/10HP
D/cmb     (25305): OCR-CP #0: ᴄᴘ10
D/cmb     (25305): OCR-Gender: ♂
D/cmb     (25305): Analyzer found all values using 1 screenshots
I/cmb     (25305): Screenshot analysis took 138ms
D/MainService(25305): Received values: Id: 3 (Charmander), Nr: 4, CP: 10, Max HP: 10, Dust cost: 200, Level: 1.0, FastMove err, SpecialMove err, Gender 1
D/UIOverlay(25305): setValues() - ID: 3 (Level 1.0), 10 CP, 10 HP, 200 dust cost
D/clx     (25305): calculateCombinations() - single level: 1.0
D/clx     (25305): Found corresponding 10CP entry in history -> don't add new scan
D/clx     (25305): calculateCombinations() - single level: 1.0
D/cly     (25305): Computed filtered combinations: 3738
I/clr     (25305): Reduced combination size from 3738 to 512 in 0ms
D/clx     (25305): calculateCombinations() - single level: 1.0
D/clx     (25305): calculateCombinations() - single level: 1.0
I/clr     (25305): calculateScanOutputData finished after 17ms
I/HwSecImmHelper(25305): mSecurityInputMethodService is null

I should also mention, I tried to run the ivcheck.py again after a phone restart, and after disabling OpenGl traces in my developer options, and this time I received this error:

2018-10-01 20:38:01,817 - PokemonGo - DEBUG - Running ['adb', 'devices']
2018-10-01 20:38:01,835 - PokemonGo - DEBUG - Return code 0
2018-10-01 20:38:01,836 - PokemonGo - DEBUG - Running ['adb', '-s', '2WMDU16A29001779', 'shell', 'pidof', '-s', 'tesmath.calcy']
2018-10-01 20:38:01,901 - PokemonGo - DEBUG - Return code 0
2018-10-01 20:38:01,902 - PokemonGo - DEBUG - Running pidof calcy got code 0: b'1\r\n'
2018-10-01 20:38:01,902 - PokemonGo - DEBUG - Starting logcat ['adb', '-s', '2WMDU16A29001779', 'logcat', '-T', '1']
2018-10-01 20:38:02,575 - PokemonGo - DEBUG - Running ['adb', '-s', '2WMDU16A29001779', 'shell', 'am broadcast -a tesmath.calcy.ACTION_ANALYZE_SCREEN -n tesmath.calcy/.IntentReceiver']
2018-10-01 20:38:04,843 - PokemonGo - DEBUG - Return code 0
/Users/Aldo/.pyenv/versions/3.7.0/lib/python3.7/asyncio/unix_events.py:861: RuntimeWarning: A loop is being detached from a child watcher with pending handlers
  RuntimeWarning)
Traceback (most recent call last):
  File "ivcheck.py", line 117, in <module>
    asyncio.run(Main(args).start())
  File "/Users/Aldo/.pyenv/versions/3.7.0/lib/python3.7/asyncio/runners.py", line 43, in run
    return loop.run_until_complete(main)
  File "/Users/Aldo/.pyenv/versions/3.7.0/lib/python3.7/asyncio/base_events.py", line 568, in run_until_complete
    return future.result()
  File "ivcheck.py", line 50, in start
    values = await self.check_pokemon()
  File "ivcheck.py", line 79, in check_pokemon
    line = await self.p.read_logcat()
  File "/Users/Aldo/Desktop/PoGO/878010c/pokemonlib.py", line 87, in read_logcat
    while line.split()[2].decode('utf-8') != self.calcy_pid:
IndexError: list index out of range
Azelphur commented 5 years ago

Seems like filtering the logs for calcy IV is a nightmare, some phones don't support the logcat --pid option, some phones apparently don't work properly with pidof. It seems like your adb logcat also doesn't output timestamps? while both of my phones do, which is the issue the above command looks like it's bumping into.

What phone are you using, and have you done done any nonstandard changes to it?

AVellucci commented 5 years ago

It's a Huawei GR5 The only "non-standard" change I've done to it is use adb to lower the resolution on the phone from 1080 to 720 so that I could run PoGO smoother.

I've also got Developer mode enabled and I've tuned what I could from the standard phone menus to make less "Quality" and more "Performance"

AVellucci commented 5 years ago

I did a quick search online about logcat and timestamping and I found this question on Stack overflow. https://stackoverflow.com/questions/15114130/time-displayed-in-logcat Maybe passing the -v argument with either time or threadtime will provide more consistent results for varying devices and their outputs, this would ensure a timestamp unless the logcat does not support timestamping in any way.

I can confirm however that threadtime and time both work for my device.

Azelphur commented 5 years ago

Hi, good find!

I decided to use the brief log format on the basis that it's probably a little less data to send between the phone and the computer, maybe it'll make things faster, but hopefully it'll also force the log format to be the same between devices.

Go ahead and give it another try, let me know if it works for you.

AVellucci commented 5 years ago

so it looks like it's working better, it definitely "goes through the motions" now, and I can see the terminal outputting the tap events and such, but I think a new problem has arisen for me now. I'll open another issue for it as I'm not sure it 's related, it may be something else now but the scan output looks to be getting properly read now

AVellucci commented 5 years ago

No new issue is needed, it was a mistake on my part, I added an additional 10px to my Y axis which was offsetting the rename tap too much and causing it to miss the tap and fail the rest. This now works like a charm, I can catch pokemon to my hearts content and then have this scan and rename everything for me. Thanks soo much for the support with my issue.