Give more info about 'got the data requested'

[wraythex]

I couldn't see a way to re-open PR968 ( #968 ), so I've opened this new PR.

Please see last question on this PR.

With this update you will be able to see more information in the 'Got the data requested' log line.
Originally all you would see is a bunch of:

[           MITMBase:177 ] [S] Got the data requested

With 968 you would have seen:

[           MITMBase:177 ] [S] Got the data requested, type = LatestReceivedType.GMO
[           MITMBase:177 ] [S] Got the data requested, type = LatestReceivedType.MON
[           MITMBase:177 ] [S] Got the data requested, type = LatestReceivedType.STOP
[           MITMBase:177 ] [S] Got the data requested, type = FortSearchResultTypes.QUEST
[           MITMBase:177 ] [S] Got the data requested, type = <data-block>

But with this new expanded logging you will see lines like:

[           MITMBase:177 ] [S] Got the data requested, type = LatestReceivedType.GMO
[           MITMBase:177 ] [S] Got the data requested, type = LatestReceivedType.MON
[           MITMBase:177 ] [S] Got the data requested, type = LatestReceivedType.STOP
[           MITMBase:177 ] [S] Got the data requested, type = FortSearchResultTypes.QUEST
[           MITMBase:177 ] [S] Got the data requested, type = <class 'dict'> size = 7816 bytes
[           MITMBase:177 ] [S] Got the data requested, type = <class 'dict'> size = 61347 bytes
[           MITMBase:177 ] [S] Got the data requested, type = <class 'dict'> size = 351232 bytes

To expand on my earlier issue, originally I found a worker had been "sitting idle" at a pokestop for 12 hours. The only thing in the MAD log was a constant repetition of:

[08-23 15:03:19.69] [           atv107] [  MITMDataProcessor:71  ] [I] Processing GMO received. Received at 2020-08-23 15:03:20
[08-23 15:03:29.77] [           atv107] [  MITMDataProcessor:71  ] [I] Processing GMO received. Received at 2020-08-23 15:03:30
[08-23 15:03:35.85] [           atv107] [           MITMBase:188 ] [W] Timeout waiting for data
[08-23 15:03:38.87] [           atv107] [           MITMBase:131 ] [I] Waiting for data after 2020-08-23 15:03:35.290276
[08-23 15:03:39.51] [           atv107] [  MITMDataProcessor:71  ] [I] Processing GMO received. Received at 2020-08-23 15:03:40
[08-23 15:03:39.88] [           atv107] [           MITMBase:174 ] [S] Got the data requested
[08-23 15:03:39.88] [           atv107] [       WorkerQuests:721 ] [I] Spin Stop
[08-23 15:03:39.89] [           atv107] [           MITMBase:131 ] [I] Waiting for data after 2020-08-23 15:03:35.488163
[08-23 15:03:40.89] [           atv107] [           MITMBase:174 ] [S] Got the data requested
[08-23 15:03:41.90] [           atv107] [       WorkerQuests:782 ] [W] Softban - return to main screen and open again...
[08-23 15:03:45.94] [           atv107] [       WorkerQuests:613 ] [W] Can't spin stop - no map info in GMO!
[08-23 15:03:45.94] [           atv107] [           MITMBase:131 ] [I] Waiting for data after 2020-08-23 15:03:42.721225
[08-23 15:03:49.45] [           atv107] [  MITMDataProcessor:71  ] [I] Processing GMO received. Received at 2020-08-23 15:03:50
[08-23 15:04:00.41] [           atv107] [  MITMDataProcessor:71  ] [I] Processing GMO received. Received at 2020-08-23 15:04:00

With this new logging I caught another worker after it had been "sitting idle" at a pokestop for 20 minutes. This time the MAD log showed a repetition of:

[09-01 08:04:32.81] [           atv108] [  MITMDataProcessor:71  ] [I] Processing GMO received. Received at 2020-09-01 08:04:31
[09-01 08:04:42.72] [           atv108] [  MITMDataProcessor:71  ] [I] Processing GMO received. Received at 2020-09-01 08:04:41
[09-01 08:04:43.31] [           atv108] [           MITMBase:188 ] [W] Timeout waiting for data
[09-01 08:04:46.39] [           atv108] [           MITMBase:131 ] [I] Waiting for data after 2020-09-01 08:04:41.273749
[09-01 08:04:47.39] [           atv108] [           MITMBase:174 ] [S] Got the data requested, type = LatestReceivedType.STOP
[09-01 08:04:47.41] [           atv108] [       WorkerQuests:721 ] [I] Spin Stop
[09-01 08:04:47.41] [           atv108] [           MITMBase:131 ] [I] Waiting for data after 2020-09-01 08:04:40.839417
[09-01 08:04:48.42] [           atv108] [           MITMBase:174 ] [S] Got the data requested, type = FortSearchResultTypes.OUT_OF_RANGE
[09-01 08:04:49.43] [           atv108] [       WorkerQuests:782 ] [W] Softban - return to main screen and open again...
[09-01 08:04:52.97] [           atv108] [  MITMDataProcessor:71  ] [I] Processing GMO received. Received at 2020-09-01 08:04:51
[09-01 08:04:53.55] [           atv108] [       WorkerQuests:613 ] [W] Can't spin stop - no map info in GMO!
[09-01 08:04:53.55] [           atv108] [           MITMBase:131 ] [I] Waiting for data after 2020-09-01 08:04:51.024755
[09-01 08:05:02.96] [           atv108] [  MITMDataProcessor:71  ] [I] Processing GMO received. Received at 2020-09-01 08:05:01
[09-01 08:05:13.22] [           atv108] [  MITMDataProcessor:71  ] [I] Processing GMO received. Received at 2020-09-01 08:05:11

So, for some reason the worker was returning "STOP" data, but also returning "OUT_OF_RANGE" data, even though when I looked at the screen of the worker it was standing directly on top of the stop to spin. I'm guessing there was a problem with the client getting game data, which I understand can happen. But, I'm wondering why MAD didn't restart/reboot the client after a few minutes of this?

Does anyone understand the internals of this and can think of a way to get the client to restart/reboot after a few minutes of this problem?

[sn0opy]

Neither "<data-block" nor "<class 'dict'> size = 351232 bytes" is really self-explaning, so we would always need to explain things to people on Discord.

I like the actual enum representation instead of the integer. I haven't looked too deep into the code yet, but I'm not even sure why that method is returning the actual data instead of its type. So there's either some part in MAD which actually requires the data to be returned or it was simply an oversight and can be replaced by a proper RecievedType

[wraythex]

Yeah, I was thinking the same thing, that either "data_requested" should always be an enum type and getting a dict was a bug somewhere, or that something else in mad was expecting a dict for its return type. I didn't look into that, as I'm not sure what the creators intentions were. I'm hoping to find a way to get my worker to restart after a few minutes of the error condition I mentioned up above.

[wraythex]

I'll stop trying to make flake happy. The code works in MAD. If you'd like to see any other changes to that logging line, please let me know.

If you'd like any more details on the error I received above, or know of something I can test to fix it, please let me know. Thanks!

[Expl0dingBanana]

@wraythex you can test flake8 locally with the following commands:

pip3 install flake8 flake8-variables-names flake8-logging-format pep8-naming flake8-eradicate
python3 -m flake8

[Expl0dingBanana]

Going to close this PR due to inactivity. Feel free to re-open when the issues are resolved.