Pyhanko does not recognize token-label anymore

[Fernando-Cabral]

After using pyhanko for about two years, today it stopped working because it does not find the token label. Here is the error message:

2022-11-16 11:03:13,725 - pyhanko.cli - ERROR - PKCS#11 error
Error: PKCS#11 error: [PKCS11Error] No token matching criteria TokenCriteria(label='**LABEL GOES HERE**', serial=None) found

This label and this token have been working for a very long time.

Only change I am aware of is that two days ago I updated a bunch of Python modules, pyhanko included. Could one of those be responsible for the failure? Any change in the code the reads the label?

Is there a way for me to have pyhanko to tell me what are the labels it is seeing?
pyHanko, version 0.15.1
Debian 11 (fully upgraded)
Python 3.9.2 (default, Feb 28 2021, 17:03:44)
[GCC 10.2.1 20210110] on linux

When run with the --verbose option I get the following:

2022-11-16 11:25:19,568 - root - DEBUG - Finished reading configuration from <_io.TextIOWrapper name='pyhanko.yml' mode='r' encoding='UTF-8'>.
2022-11-16 11:25:19,591 - PIL.PngImagePlugin - DEBUG - STREAM b'IHDR' 16 13
2022-11-16 11:25:19,591 - PIL.PngImagePlugin - DEBUG - STREAM b'zTXt' 41 7938
2022-11-16 11:25:19,592 - PIL.PngImagePlugin - DEBUG - STREAM b'iCCP' 7991 388
2022-11-16 11:25:19,592 - PIL.PngImagePlugin - DEBUG - iCCP profile name b'ICC profile'
2022-11-16 11:25:19,592 - PIL.PngImagePlugin - DEBUG - Compression method 0
2022-11-16 11:25:19,592 - PIL.PngImagePlugin - DEBUG - STREAM b'bKGD' 8391 6
2022-11-16 11:25:19,592 - PIL.PngImagePlugin - DEBUG - b'bKGD' 8391 6 (unknown)
2022-11-16 11:25:19,592 - PIL.PngImagePlugin - DEBUG - STREAM b'pHYs' 8409 9
2022-11-16 11:25:19,592 - PIL.PngImagePlugin - DEBUG - STREAM b'tIME' 8430 7
2022-11-16 11:25:19,592 - PIL.PngImagePlugin - DEBUG - b'tIME' 8430 7 (unknown)
2022-11-16 11:25:19,592 - PIL.PngImagePlugin - DEBUG - STREAM b'IDAT' 8449 8192
2022-11-16 11:25:22,902 - pyhanko.cli - ERROR - PKCS#11 error
Traceback (most recent call last):
  File "/home/fernando/.local/lib/python3.9/site-packages/pyhanko/cli.py", line 1191, in addsig_pkcs11
    with pkcs11.PKCS11SigningContext(pkcs11_config, user_pin=pin) as signer:
  File "/home/fernando/.local/lib/python3.9/site-packages/pyhanko/sign/pkcs11.py", line 721, in __enter__
    return self._instantiate()
  File "/home/fernando/.local/lib/python3.9/site-packages/pyhanko/sign/pkcs11.py", line 705, in _instantiate
    self._session = session = open_pkcs11_session(
  File "/home/fernando/.local/lib/python3.9/site-packages/pyhanko/sign/pkcs11.py", line 366, in open_pkcs11_session
    raise PKCS11Error(
pkcs11.exceptions.PKCS11Error: No token matching criteria TokenCriteria(label="FERNANDO JOSE CASTRO CABRAL:12436666687's AC VALID RFB v5 ID", serial=None) found
Error: PKCS#11 error: [PKCS11Error] No token matching criteria TokenCriteria(label="FERNANDO JOSE CASTRO CABRAL:12436666687's AC VALID RFB v5 ID", serial=None) found

[MatthiasValvekens]

Hi,

That's a difficult question to answer without context. Do you know the previous pyHanko version you had installed? If you updated recently, perhaps the old package file is still sitting somewhere in your package manager's cache. That info would help to gauge how the behaviour changed between versions.

What would be even more helpful: if you could try out different pyHanko versions until you find the version that introduced the breaking change, that'd be great.

[MatthiasValvekens]

Yeah, sorry about the exception not being imported, I was in a bit of a rush there.

So, if I read your output correctly, the label of the token is actually "token ONLINE" or "Token ONLINE" (?), and not what you wrote earlier. I don't understand why this worked before, though. Perhaps there was another bug in the CLI logic that caused the label not to be passed to the PKCS#11 session init function, which would've made it so that pyHanko always picked the first available token when called from the CLI.

[Fernando-Cabral]

You said:

So, if I read your output correctly, the label of the token is actually "token ONLINE" or "Token ONLINE" (?), and not what you wrote earlier.
Well, I tested this hypothesis too. I tried to trick it around so I replaced the token-label with token ONLINE. Did not work the same. Same error message.
Now, using tokenadmin, the tool the comes with the token, I see this label too:

Above it says: Reader's or token's name : token ONLINE , operational.

In the above message we see Rótulo (Label) as "FERNANDO..... 124..." but we also see Rótulo do token (token's label) as token ONLINE.
Anyway, up to pyhanko version 0.13.0 it only accepted the label "FERNANDO....". Now it accepts neither "FERNANDO.." nor "token ONLINE"; it only accepts "slot-no: 0"

[MatthiasValvekens]

While I still don't understand exactly what changed in pyHanko's behaviour, I think "Token ONLINE" is the actual token's label, while FERNANDO .... is the label of the certificate object and/or key object inside the token. Note that the label is case sensitive as far as pyHanko is concerned; did you try both Token ONLINE and token ONLINE?

My current working hypothesis is that the old version was bugged, and your invocation simply worked until now by accident... I only set up the infrastructure to test the PKCS#11 signing code in CI a few months ago; before that, it was very poorly tested.

[Fernando-Cabral]

I had not tried Token ONLINE (with uppercase T). I did as you suggested and It worked. So I had been using a label that in fact was not a label! For some reason, pyhanko let it go in the past but does not allow it any more.
Mystery solved, I guess.

[MatthiasValvekens]

Glad to hear that you (kinda) got it solved!