Failed to get file info: Data must be aligned to block boundary in ECB mode

[Jonybat]

Hi

I seem to be getting these errors quite often. I haven't been able to figure out exactly what is causing them, but running anidbcli less frequently seems to alleviate it, which leads me to believe that its yet another API issue. It is not file dependent, as running some minutes/hours later on the same file, does not throw the error anymore.

This is the log:

[SUCCESS] Generated ed2k link.
[ERROR] Failed to get file info: Data must be aligned to block boundary in ECB mode

And after removing the except in line 72 of operations.py:

[SUCCESS] Generated ed2k link.
Traceback (most recent call last):
  File "/opt/anidbcli/bin/anidbcli", line 11, in <module>
    load_entry_point('\''anidbcli==1.53'\'', '\''console_scripts'\'', '\''anidbcli'\'')()
  File "/opt/anidbcli/lib/python3.6/site-packages/anidbcli/cli.py", line 139, in main
    cli(obj={})
  File "/opt/anidbcli/lib/python3.6/site-packages/Click-7.0-py3.6.egg/click/core.py", line 764, in __call__
    return self.main(*args, **kwargs)
  File "/opt/anidbcli/lib/python3.6/site-packages/Click-7.0-py3.6.egg/click/core.py", line 717, in main
    rv = self.invoke(ctx)
  File "/opt/anidbcli/lib/python3.6/site-packages/Click-7.0-py3.6.egg/click/core.py", line 1137, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/opt/anidbcli/lib/python3.6/site-packages/Click-7.0-py3.6.egg/click/core.py", line 956, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/opt/anidbcli/lib/python3.6/site-packages/Click-7.0-py3.6.egg/click/core.py", line 555, in invoke
    return callback(*args, **kwargs)
  File "/opt/anidbcli/lib/python3.6/site-packages/Click-7.0-py3.6.egg/click/decorators.py", line 17, in new_func
    return f(get_current_context(), *args, **kwargs)
  File "/opt/anidbcli/lib/python3.6/site-packages/anidbcli/cli.py", line 84, in api
    res = operation.Process(file_obj)
  File "/opt/anidbcli/lib/python3.6/site-packages/anidbcli/operations.py", line 70, in Process
    res = self.connector.send_request(API_ENDPOINT_FILE % (file["size"], file["ed2k"]))
  File "/opt/anidbcli/lib/python3.6/site-packages/anidbcli/anidbconnector.py", line 117, in send_request
    res = self.crypto.Decrypt(res)
  File "/opt/anidbcli/lib/python3.6/site-packages/anidbcli/encryptors.py", line 28, in Decrypt
    ret = self.aes.decrypt(message)
  File "/opt/anidbcli/lib/python3.6/site-packages/Crypto/Cipher/_mode_ecb.py", line 195, in decrypt
    raise ValueError("Data must be aligned to block boundary in ECB mode")
ValueError: Data must be aligned to block boundary in ECB mode'

[adameste]

Caused by decryption, app probably did not receive all the data from the api, so the decryption failed as it needs the data length to be divisible by 16... I could not reproduce this. Could be error on server side, because if the data is longer than max packet size, then api sends them in 2 separate packets... and this is an issue with the packet itself. You can look into it further using wireshark or some other packet capture app and see what is going on.

[adameste]

Maybe fixed? I had the wrong max_udp_packet size set, so it's possible I ignored part of the packet. Try with version 1.54

[Jonybat]

Sorry, I forgot about this. I'll try to look at it during the weekend.

[Jonybat]

Just updated to 1.60, got it happening again. Here is a tcpdump of when it fails:

16:12:19.036487 IP (tos 0x0, ttl 64, id 46472, offset 0, flags [DF], proto UDP (17), length 140)
    192.168.0.1.43333 > 94.130.237.200.9000: [udp sum ok] UDP, length 112
        0x0000:  4500 008c b588 4000 4011 77e4 c0a8 0001  E.....@.@.w.....
        0x0010:  5e82 edc8 a945 2328 0078 226f 4532 d904  ^....E#(.x"oE2..
        0x0020:  4173 f168 fbb8 4380 98bc bfb1 6e6a 03ba  As.h..C.....nj..
        0x0030:  8f8a 7ad7 6a28 dca7 3e86 0ab7 dc09 019b  ..z.j(..>.......
        0x0040:  96bf ca1d e629 a243 9811 fb06 895b 5c00  .....).C.....[\.
        0x0050:  6e0d 1a4b 238c 80e6 e3b9 70b0 cb46 dd05  n..K#.....p..F..
        0x0060:  eb1b 9802 283a b323 b683 f3c2 1d70 c63c  ....(:.#.....p.<
        0x0070:  32ad 969d 83cf c816 85e3 2f10 d213 bbf2  2........./.....
        0x0080:  e122 b758 7a0c 4bf5 0191 004e            .".Xz.K....N
16:12:19.151492 IP (tos 0x0, ttl 51, id 55768, offset 0, flags [DF], proto UDP (17), length 48)
    94.130.237.200.9000 > 192.168.0.1.43333: [udp sum ok] UDP, length 20
        0x0000:  4500 0030 d9d8 4000 3311 60f0 5e82 edc8  E..0..@.3.`.^...
        0x0010:  c0a8 0001 2328 a945 001c 64f1 3539 3820  ....#(.E..d.598.
        0x0020:  554e 4b4e 4f57 4e20 434f 4d4d 414e 440a  UNKNOWN.COMMAND.

Edit: could it be something to do with the socket that you implemented a while back? It seems that after a while has passed, and I try to run this again, I see what appears to be auth and encryption negotiation in tcpdump. If the socket expires after a while, it explains why it starts working if I just wait. I didn't remember to check this but now it came to mind. I might look at it again tomorrow.

[adameste]

Seems to me, that the connection session was closed on anidb side and common secret (key + salt) no longer match and/or anidb no longer expect encrypted messages, so it sends unencrypted UNKNOWN COMMAND response, which anidbcli fails to handle. Maybe reducing the new session treshold to something more reasonable (like 5 minutes) might help. It can be found in file cli.py, line 97. Just try changing that 34 to 5 and report results. I invoke anidbcli just once to parse all the files at once and never encountered this problem.

[adameste]

Actually included it in version 1.61, so you can just update.

[Jonybat]

I guess that might be it, because it explains why I have this issue if I run it on a scheduled task every 30m, but not if I change the interval to 1h.

Anyway, initial test seems OK, but i didn't get to the bottom of it before, because I'm still not sure how to reproduce it reliably. Let's call it fixed for now, thanks.