Service: Error retrieving documents from Alma: Unexpected token u in JSON at position 0.

[dregad]

Today, our APD (running as a service) stopped working.

Here is the last entry in the log file, occurring after a long series of Printed document {ID} on {PRINTER}. messages, the last one at 2024-04-30T07:26:44.050Z:

2024-04-30T07:28:05.655Z:  Service: Error retrieving documents from Alma:  Unexpected token u in JSON at position 0. Reset timer to try again.

We were able to restore normal operations by stopping and restarting the service.

Any ideas what could have been causing this ? This error often occurs when JSON.parse is called on undefined, which could be the result of some improperly handled error or exception.

[mgobat]

@dregad, does the reported error message appear multiple times in succession? The error indicates that it is going to reset the timer and try again. If the error only appears once, then the timer isn't getting triggered to try again. If it appears multiple times, then the timer is triggering but something else is preventing the retrieval from succeeding. Knowing this might help determine where the problem lies. Thanks.

[dregad]

Only once.

[mgobat]

@dregad, let's start with the easy question. Were any Printers changed/deleted in Alma that were configured in the Alma Print Daemon? Alma Printers are defined in Alma at "Configuration > Fulfillment > Printers". If so, perhaps the Alma Print Daemon needs to be reconfigured. If not, let's see if we can trap the response from the API that the Alma Print Daemon is calling to retrieve the documents to print.

The API to retrieve all documents to print in all the Alma Printer Queues looks like this:

https://api-eu.hosted.exlibrisgroup.com/almaws/v1/task-lists/printouts?status=Pending&printer_id=ALL&limit=100&apiKey=YOUR_API_KEY_HERE

Replace the YOUR_API_KEY_HERE with the actual API key used in the Alma Print Daemon configuration. Then copy the full URL and paste it into your web browser address bar. The API response should appear in the browser window. Please report back what appears in the web browser. Please check for anything sensitive in the response before posting publicly; I'm hoping it is just an error message, though. Thanks.

[dregad]

Apologies for the delay, I have been out of the office.

To my knowledge, there have been no changes in Alma configuration, but I'll double check with my colleague who manages that, when he comes back on Monday. The (unchanged) APD configuration did not trigger any visible errors in the logs though, other than what I reported earlier.

Please find attached the output of the requested API call; there was no error (HTTP 200). api_output.zip

I have marked removed information with {{REDACTED}} (user names and document contents)

[dregad]

While I was writing the above note, the error appeared in the log file again, 3 times in a row:

2024-05-03T13:22:33.930Z:  Printed document 5934484180005524 on \\srvimp01p.activedir.ville-geneve.ch\60568_UPCL.
2024-05-03T13:25:26.078Z:  Service: Error retrieving documents from Alma:  Unexpected token u in JSON at position 0. Reset timer to try again.
2024-05-03T13:26:17.102Z:  Service: Error retrieving documents from Alma:  Unexpected token u in JSON at position 0. Reset timer to try again.
2024-05-03T13:27:08.113Z:  Service: Error retrieving documents from Alma:  Unexpected token u in JSON at position 0. Reset timer to try again.
2024-05-03T13:44:26.654Z:  Printed document 5934537370005524 on \\srvimp01p.activedir.ville-geneve.ch\60568_UPCL.

But as far as I can tell the process kept on running normally, since there are other, successfully printed documents after the error (as shown above).

[mgobat]

@dregad, thanks for the api output zip file. Yes, the response looks totally normal.

Where the error appeared three times is interesting in that it looks like the error trapping is working, resetting the timer, and then asking for the printouts again. This is expected behavior when there is an error retrieving the printouts. And it appears in the log that it picked up printing again successfully after the third error message.

Have there been any reports of printouts that have been missing? Are there printouts still in the Printouts Queue in Alma (Admin > Printouts queue) that the Alma Print Daemon should have printed?

Unsure why the printing didn't get picked up again in your original report, and that you had to restart to get it going again. We'll take another look at the code. It generates the "reset timer" log message in two places. We'll look at the code in both places to see if there are any differences that may have caused the printing to not restart the first time.

Thanks.

[dregad]

Hello @mgobat thanks for your patience. My colleague confirms that

• there have been no changes in configuration, neither in Alma nor in APD.
• No print jobs were left pending in the Alma Printouts queue
• The pending jobs in the file I sent you, are in (currently) disabled queues, which are not configured or processed by APD

It's worth mentioning that, on the day the problem occurred, there was another APD client running interactively on a user's workstation (i.e. in addition to the one running as a service on our print server), which was started as a troubleshooting / workaround for the problem of documents not being printed which was solved by restarting the Windows service.

I don't know if that could be the cause for the Unexpected token u in JSON error.

According to my colleague, this does explain 2 occurrences of an error 40166412, which we found in the logs after restarting the service. This is something that I did not report here initially, as I didn't think it was relevant. Here are the log entries, just in case

2024-04-30T14:48:33.194Z:  Successfully printed document 5894741470005524 on [\\srvimp01p.activedir.ville-geneve.ch\60568_UPCL](file:///60568_UPCL).
2024-04-30T14:48:34.551Z:  Printed document 5894741470005524 on [\\srvimp01p.activedir.ville-geneve.ch\60568_UPCL](file:///60568_UPCL).
2024-04-30T14:48:34.746Z:  Service: Printing document 5894741470005524 failed on 937109020005524. Skipping to next document.
2024-04-30T14:48:34.747Z:  Service: Print error Failed to perform action. Error: PrintedStatus (40166412)
2024-04-30T14:48:34.791Z:  Successfully printed document 5894742310005524 on [\\srvimp01p.activedir.ville-geneve.ch\60568_UPCL](file:///60568_UPCL).
2024-04-30T14:48:37.626Z:  Printed document 5894742310005524 on [\\srvimp01p.activedir.ville-geneve.ch\60568_UPCL](file:///60568_UPCL).
2024-04-30T14:48:37.816Z:  Service: Printing document 5894742310005524 failed on 937109020005524. Skipping to next document.
2024-04-30T14:48:37.817Z:  Service: Print error Failed to perform action. Error: PrintedStatus (40166412)

[mgobat]

Hi @dregad...

Your latest log snippet includes log messages that occur when the APD is run as a service and log messages that occur when it is run interactively on the workstation. Is it possible that it was also running interactively on the server/workstation running the APD as a service?

You mentioned in your comment that the APD was also running interactively on a user's workstation. Was it a shared copy of the APD executable that the service is running? I can't think of any other way both message types would appear in the log. If a shared copy is in play, then that could explain the errors in the latest log snippet.

Also, the printing process is two-fold:

1. Print the document
2. Tell Alma the document has been printed

The same error trapping is used for both processes, so it is possible that the error is being generated if the "mark as printed" is failing after successfully printing the document.

We'll take another look at the code.

[dregad]

Is it possible that it was also running interactively on the server/workstation running the APD as a service?

Yes absolutely, I was connected to the server where the APD service is running, and started the client under my session to check the configuration.

I don't know if that is feasible, but it would be great if in such scenario, the system could somehow detect that the APD service is running (or configured for centralized configuration), and not actually attempt to process the queues in this case, it would avoid such confusing log entries.

Was it a shared copy of the APD executable that the service is running?

No, it was not a shared copy, but a fully separate, independent installation.

the printing process is two-fold

Do I understand correctly, that this design could cause the same job to be printed multiple times if more than one APD is running ? Note that this is a theoretical question, it did not actually happen to us, as far as I know.

[mgobat]

@dregad, yes, if multiple copies of the APD are running and servicing the same Alma Print Queues, printouts may be duplicated. Until a document is marked as printed, it is eligible to be sent to a running instance of the APD.

[mgobat]

@dregad, these two messages appear in the log because the printout was already marked as having been printed, and then it tried to mark the printout as printed again, caused by the service and the interactive session processing the same printouts.

2024-04-30T14:48:37.816Z:  Service: Printing document 5894742310005524 failed on 937109020005524. Skipping to next document.
2024-04-30T14:48:37.817Z:  Service: Print error Failed to perform action. Error: PrintedStatus (40166412)

[dregad]

these two messages appear in the log because the printout was already marked as having been printed

OK, thanks for clarifying. Maybe the wording of the log message could be improved to reflect this, so it does not misleading unknowing users like me into thinking something went wrong.

Based on your feedback, it would seem that most of the errors we saw were red herrings, caused by concurrent access to the print queues.

So the only question that remains, is why are we getting these Unexpected token u in JSON at position 0. errors, which do continue to pop-up in the logs almost every day ? For the record, I also got a variant Unexpected token < in JSON at position 0 too (a series of 20 occurrences on 2024-05-04 between 22:41:46 and 22:53:48, which is outside of our office hours).

[mgobat]

Hi @dregad...

Yes, some of the log messages should be improved, and indicate whether they are a result of running as a service or interactively.

I agree that most of the errors you've seen in the log aren't too relevant. When the API to retrieve printouts returns an unexpected response, the APD should reset the timer to try again. If the APD is still running when Alma is cycled, like during routine maintenance or new releases, or when having network issues, the API calls will fail, but it should pick up again when it finally gets the expected response. We saw that in one of your log snippets where the API errored 3 times but then picked up printing again. If the log indicates that the API failed and the timer is reset, yet printing never picks back up again, then that's an issue we should investigate. Your initial report seemed to be such an issue, to which I haven't found a reasonable explanation yet.

[dregad]

OK, thank you. Let me know if you need further information.