openhab-addons icon indicating copy to clipboard operation
openhab-addons copied to clipboard

Published 20 hours ago • verified publisher icon openhab

[IPP] "bad request" warnings in OH log.

Open scatterthought opened this issue 2 years ago • 5 comments

Expected Behavior

I implemented IPP to connect to a CUPS print server, which worked without issue for a long time. I expected that this would continue after I upgraded from OH 3.2 to OH 3.3.

Current Behavior

After upgrading to OH 3.3 this past week, I'm getting this warning message spammed in the log endlessly:

2022-10-07 15:24:09.310 [WARN ] [ethz.vppserver.ippclient.IppResponse] - <!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN" "http://www.w3.org/TR/html4/loose.dtd">
<HTML>
<HEAD>
	<META HTTP-EQUIV="Content-Type" CONTENT="text/html; charset=utf-8">
	<TITLE>Bad Request - CUPS v2.2.10</TITLE>
	<LINK REL="STYLESHEET" TYPE="text/css" HREF="/cups.css">
</HEAD>
<BODY>
<H1>Bad Request</H1>
<P></P>
</BODY>
</HTML>

I thought that maybe I need to remove and re-add the thing that was carried over from OH3.2. I did that and there were no warnings for 12+ hours, but then the warnings started again and continued until I disabled the thing. Every minute, there are three warnings every minute (likely corresponding to the default 60-second refresh rate of the IPP binding). After the warnings start, CUPS stops talking openHAB.

If I go back to OH 3.2, there are no warnings and everything works fine.

Possible Solution

I'm not sure if this is a bug with the IPP binding or if it's an issue with my cupsd.conf configuration. I'm able to access the CUPS server remotely from my Windows desktop PC, and connections from openHAB definitely work for a period of time before the warning starts. I ran the cupsctl --share-printers command in the CUPS documentation to ensure my cupsd.conf is baseline.

I'm guessing that these warnings are now showing up due to this commit by @wborn, which seems to be the only change to the IPP binding between the stable releases of 3.2 and 3.3. Nothing has changed on my CUPS 2.2.10 server, which is on a different Raspberry Pi on the same network. There doesn't appear to be a newer CUPS version available for Debian at this time.

https://github.com/openhab/openhab-addons/commit/03e626018d26ef548d0ca80da3ae4e13a13e5a0a

Since these are just warnings, I thought about raising the log level for the binding. However, it now seems that they are communication between openHAB and CUPS is not being maintained.

Steps to Reproduce (for Bugs)

  1. Set up a CUPS server and printer on Debian
  2. Connect to the CUPS server from openHAB using the IPP binding
  3. Monitor log to see if warnings appear

Your Environment

  • Version used: OH 3.3 (stable), stable IPP binding
  • CUPS 2.2.10 runs on an octoPi image (Raspian Buster)

scatterthought avatar Oct 07 '22 22:10 scatterthought

You can also increase the log level of cupsd in /etc/cups/cupsd.conf, maybe that helps with explaining why the error occurs.

#
# Configuration file for the CUPS scheduler.  See "man cupsd.conf" for a
# complete description of this file.
#

# Log general information in error_log - change "warn" to "debug"
# for troubleshooting...
LogLevel warn
PageLogFormat

wborn avatar Oct 08 '22 19:10 wborn

Oh, good idea. I'm away this weekend, but I'll try that when I'm back home.

scatterthought avatar Oct 08 '22 20:10 scatterthought

I increased the log level, but nothing happened for awhile. I rebooted my CUPS server to see if that would do anything, and after CUPS restarted it gave me three of the warnings above. I checked the CUPS log and found three corresponding errors on requests from my openHAB server:

Request from "192.168.1.100" using invalid Host: field "localhost".

D [11/Oct/2022:21:52:24 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [11/Oct/2022:21:52:24 -0700] [Client 1] Server address is "192.168.1.101".
D [11/Oct/2022:21:52:24 -0700] [Client 1] Accepted from 192.168.1.100:42514 (IPv4)
D [11/Oct/2022:21:52:24 -0700] [Client 1] Waiting for request.
D [11/Oct/2022:21:52:24 -0700] [Client 1] POST /printers/Brother_HL-2140_series HTTP/1.1
D [11/Oct/2022:21:52:24 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [11/Oct/2022:21:52:24 -0700] [Client 1] Read: status=200, state=6
D [11/Oct/2022:21:52:24 -0700] [Client 1] No authentication data provided.
E [11/Oct/2022:21:52:24 -0700] [Client 1] Request from "192.168.1.100" using invalid Host: field "localhost".
D [11/Oct/2022:21:52:24 -0700] [Client 1] cupsdSendHeader: code=400, type="text/html", auth_type=0
D [11/Oct/2022:21:52:24 -0700] [Client 1] Closing on unexpected HTTP read state HTTP_STATE_POST_SEND.
D [11/Oct/2022:21:52:24 -0700] [Client 1] Closing connection.
D [11/Oct/2022:21:52:24 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [11/Oct/2022:21:52:24 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [11/Oct/2022:21:52:24 -0700] [Client 2] Server address is "192.168.1.101".
D [11/Oct/2022:21:52:24 -0700] [Client 2] Accepted from 192.168.1.100:42518 (IPv4)
D [11/Oct/2022:21:52:24 -0700] [Client 2] Waiting for request.
D [11/Oct/2022:21:52:24 -0700] [Client 2] POST /printers/Brother_HL-2140_series HTTP/1.1
D [11/Oct/2022:21:52:24 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [11/Oct/2022:21:52:24 -0700] [Client 2] Read: status=200, state=6
D [11/Oct/2022:21:52:24 -0700] [Client 2] No authentication data provided.
E [11/Oct/2022:21:52:24 -0700] [Client 2] Request from "192.168.1.100" using invalid Host: field "localhost".
D [11/Oct/2022:21:52:24 -0700] [Client 2] cupsdSendHeader: code=400, type="text/html", auth_type=0
D [11/Oct/2022:21:52:24 -0700] [Client 2] Closing on unexpected HTTP read state HTTP_STATE_POST_SEND.
D [11/Oct/2022:21:52:24 -0700] [Client 2] Closing connection.
D [11/Oct/2022:21:52:24 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [11/Oct/2022:21:52:24 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [11/Oct/2022:21:52:24 -0700] [Client 3] Server address is "192.168.1.101".
D [11/Oct/2022:21:52:24 -0700] [Client 3] Accepted from 192.168.1.100:42520 (IPv4)
D [11/Oct/2022:21:52:24 -0700] [Client 3] Waiting for request.
D [11/Oct/2022:21:52:24 -0700] [Client 3] POST /printers/Brother_HL-2140_series HTTP/1.1
D [11/Oct/2022:21:52:24 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [11/Oct/2022:21:52:24 -0700] [Client 3] Read: status=200, state=6
D [11/Oct/2022:21:52:24 -0700] [Client 3] No authentication data provided.
E [11/Oct/2022:21:52:24 -0700] [Client 3] Request from "192.168.1.100" using invalid Host: field "localhost".
D [11/Oct/2022:21:52:24 -0700] [Client 3] cupsdSendHeader: code=400, type="text/html", auth_type=0
D [11/Oct/2022:21:52:24 -0700] [Client 3] Closing on unexpected HTTP read state HTTP_STATE_POST_SEND.
D [11/Oct/2022:21:52:24 -0700] [Client 3] Closing connection.

After that, the errors went away and my openHAB server connected normally.

D [11/Oct/2022:22:01:37 -0700] [Client 18] Returning IPP successful-ok for Get-Jobs (http://192.168.1.101/printers/Brother_HL-2140_series) from 192.168.1.100.
D [11/Oct/2022:22:01:37 -0700] [Client 18] Content-Length: 5234
D [11/Oct/2022:22:01:37 -0700] [Client 18] cupsdSendHeader: code=200, type="application/ipp", auth_type=0

I made a change to CUPSD.conf, and when CUPS restarted, I got three more errors. I also got these in my openHAB log:

2022-10-11 22:28:11.185 [ERROR] [p.internal.handler.IppPrinterHandler] - malformed url http://2001:569:bb32:6200:2fea:f001:5eac:38a:631/printers/Brother_HL-2140_series, printer thing creation failed
2022-10-11 22:28:11.188 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler IppPrinterHandler tried updating the thing status although the handler was already disposed.
2022-10-11 22:28:11.190 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler IppPrinterHandler tried updating the thing status although the handler was already disposed.
2022-10-11 22:28:11.191 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler IppPrinterHandler tried updating the thing status although the handler was already disposed.
2022-10-11 22:28:11.193 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler IppPrinterHandler tried updating the thing status although the handler was already disposed.
2022-10-11 22:28:11.194 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler IppPrinterHandler tried updating the thing status although the handler was already disposed.
2022-10-11 22:30:21.601 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler IppPrinterHandler tried updating the thing status although the handler was already disposed.
2022-10-11 22:30:21.603 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler IppPrinterHandler tried updating the thing status although the handler was already disposed.
2022-10-11 22:30:21.603 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler IppPrinterHandler tried updating the thing status although the handler was already disposed.
2022-10-11 22:30:21.604 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler IppPrinterHandler tried updating the thing status although the handler was already disposed.
2022-10-11 22:30:21.605 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler IppPrinterHandler tried updating the thing status although the handler was already disposed.

And then these warnings just stop.

The malformed URL is interesting. At some point, openHAB replaced the CUPS server's IPv4 address (192.168.1.100) with an IPv6 address:

image

I changed it back to IPv4, and when I looked a few minutes later it was back to being IPv6. I also tried changing it to the hostname, and it got changed back to IPvt. I'm not sure why that would start happening now (I'm almost certain it didn't happen in OH 3.2), or if it's even related to this issue.

This still doesn't explain why I started getting spammed with the bad-request errors, or why it only started with OH 3.3. I'm thinking that I might delete and recreate the CUPS printer to give it a fresh start, and see if it happens again. Is there anything else you think I should try first?

scatterthought avatar Oct 12 '22 05:10 scatterthought

The URL is probably updated based on the discovery result of the IppPrinterDiscoveryParticipant. That's useful whenever the IP changes. If IPv6 is the issue you could disable that or maybe ignore the discovery result and create your own thing.

wborn avatar Oct 12 '22 05:10 wborn

If IPv6 is the issue you could disable that or maybe ignore the discovery result and create your own thing.

Ah, that's why I never noticed. I think I had previously added the thing manually, but I replaced it with the discovered result while trying to troubleshoot this issue.

I'll leave everything alone to see if the the warnings start popping up again. If they do, I'll delete and re-add the printer to CUPS to see if that solves the problem.

scatterthought avatar Oct 12 '22 06:10 scatterthought

The warnings started again, so I deleted and readded the CUPS printer. It worked fine for awhile and then I saw the cycle of three warnings every minute in the OH log. Here's one of those cycles from the CUPS log, which is almost (but not quite) the same as the one from three days ago.

D [13/Oct/2022:15:57:15 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [13/Oct/2022:15:57:15 -0700] [Client 2866] Server address is "192.168.1.101".
D [13/Oct/2022:15:57:15 -0700] [Client 2866] Accepted from [192.168.1.100:53618](http://192.168.1.100:53618/) (IPv4)
D [13/Oct/2022:15:57:15 -0700] [Client 2866] Waiting for request.
D [13/Oct/2022:15:57:15 -0700] cupsdAddCert: Adding certificate for PID 0
D [13/Oct/2022:15:57:15 -0700] Report: clients=1
D [13/Oct/2022:15:57:15 -0700] Report: jobs=0
D [13/Oct/2022:15:57:15 -0700] Report: jobs-active=0
D [13/Oct/2022:15:57:15 -0700] Report: printers=1
D [13/Oct/2022:15:57:15 -0700] Report: stringpool-string-count=2481
D [13/Oct/2022:15:57:15 -0700] Report: stringpool-alloc-bytes=9400
D [13/Oct/2022:15:57:15 -0700] Report: stringpool-total-bytes=47376
D [13/Oct/2022:15:57:15 -0700] [Client 2866] POST /printers/Brother_HL-2140_series HTTP/1.1
D [13/Oct/2022:15:57:15 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [13/Oct/2022:15:57:15 -0700] [Client 2866] Read: status=200, state=6
D [13/Oct/2022:15:57:15 -0700] [Client 2866] No authentication data provided.
E [13/Oct/2022:15:57:15 -0700] [Client 2866] Request from "192.168.1.100" using invalid Host: field "localhost".
D [13/Oct/2022:15:57:15 -0700] [Client 2866] cupsdSendHeader: code=400, type="text/html", auth_type=0
D [13/Oct/2022:15:57:15 -0700] [Client 2866] Closing on unexpected HTTP read state HTTP_STATE_POST_SEND.
D [13/Oct/2022:15:57:15 -0700] [Client 2866] Closing connection.
D [13/Oct/2022:15:57:15 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [13/Oct/2022:15:57:15 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [13/Oct/2022:15:57:15 -0700] [Client 2867] Server address is "192.168.1.101".
D [13/Oct/2022:15:57:15 -0700] [Client 2867] Accepted from [192.168.1.100:53620](http://192.168.1.100:53620/) (IPv4)
D [13/Oct/2022:15:57:15 -0700] [Client 2867] Waiting for request.
D [13/Oct/2022:15:57:15 -0700] [Client 2867] POST /printers/Brother_HL-2140_series HTTP/1.1
D [13/Oct/2022:15:57:15 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [13/Oct/2022:15:57:15 -0700] [Client 2867] Read: status=200, state=6
D [13/Oct/2022:15:57:15 -0700] [Client 2867] No authentication data provided.
E [13/Oct/2022:15:57:15 -0700] [Client 2867] Request from "192.168.1.100" using invalid Host: field "localhost".
D [13/Oct/2022:15:57:15 -0700] [Client 2867] cupsdSendHeader: code=400, type="text/html", auth_type=0
D [13/Oct/2022:15:57:15 -0700] [Client 2867] Closing on unexpected HTTP read state HTTP_STATE_POST_SEND.
D [13/Oct/2022:15:57:15 -0700] [Client 2867] Closing connection.
D [13/Oct/2022:15:57:15 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [13/Oct/2022:15:57:15 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [13/Oct/2022:15:57:15 -0700] [Client 2868] Server address is "192.168.1.101".
D [13/Oct/2022:15:57:15 -0700] [Client 2868] Accepted from [192.168.1.100:53622](http://192.168.1.100:53622/) (IPv4)
D [13/Oct/2022:15:57:15 -0700] [Client 2868] Waiting for request.
D [13/Oct/2022:15:57:15 -0700] [Client 2868] POST /printers/Brother_HL-2140_series HTTP/1.1
D [13/Oct/2022:15:57:15 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [13/Oct/2022:15:57:15 -0700] [Client 2868] Read: status=200, state=6
D [13/Oct/2022:15:57:15 -0700] [Client 2868] No authentication data provided.
E [13/Oct/2022:15:57:15 -0700] [Client 2868] Request from "192.168.1.100" using invalid Host: field "localhost".
D [13/Oct/2022:15:57:15 -0700] [Client 2868] cupsdSendHeader: code=400, type="text/html", auth_type=0
D [13/Oct/2022:15:57:15 -0700] [Client 2868] Closing on unexpected HTTP read state HTTP_STATE_POST_SEND.
D [13/Oct/2022:15:57:15 -0700] [Client 2868] Closing connection.
D [13/Oct/2022:15:57:15 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"

I tried disabling IPv6, but the warnings still came back so that's not related.

What would I have to do to get a 3.2 version .jar file? (I have no idea how to compile code from Github). I'm thinking I can at least rule the binding out by installing 3.2 manually and seeing if that does the same thing.

scatterthought avatar Oct 15 '22 01:10 scatterthought

You can use this org.openhab.binding.ipp-3.2.0.jar to test if the library upgrade caused any issues.

wborn avatar Oct 15 '22 08:10 wborn

It seems like it doesn't like the "localhost" Host field value

E [13/Oct/2022:15:57:15 -0700] [Client 2868] Request from "192.168.1.100" using invalid Host: field "localhost".
D [13/Oct/2022:15:57:15 -0700] [Client 2868] cupsdSendHeader: code=400, type="text/html", auth_type=0

The HTTP response code 400 is probably the "Bad request" of the response in your first comment.

wborn avatar Oct 15 '22 08:10 wborn

I have the same issue. I searched for that invalid Host message and just found out that adding ServerAlias localhost to /etc/cups/cupsd.conf on the machine running cups fixes the issue. If anyone sees that error message with something other than localhost, my guess is that you should add that other hostname instead.

Rapti avatar Oct 15 '22 16:10 Rapti

Thanks, I'll try ServerAlias localhost first, and the 3.2 binding if that doesn't help. I came across some CUPS posts (from a decade ago) talking about ServerAlias, but it didn't occur to me to try it with localhost.

It's so strange that it only starts throwing CUPS errors after running for awhile. And in the last log I posted, it seems like it's accepting and rejecting requests at the same time.

E [13/Oct/2022:15:57:15 -0700] [Client 2866] Request from "192.168.1.100" using invalid Host: field "localhost".
D [13/Oct/2022:15:57:15 -0700] [Client 2866] cupsdSendHeader: code=400, type="text/html", auth_type=0
D [13/Oct/2022:15:57:15 -0700] [Client 2866] Closing on unexpected HTTP read state HTTP_STATE_POST_SEND.
D [13/Oct/2022:15:57:15 -0700] [Client 2866] Closing connection.
D [13/Oct/2022:15:57:15 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [13/Oct/2022:15:57:15 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [13/Oct/2022:15:57:15 -0700] [Client 2867] Server address is "192.168.1.101".
D [13/Oct/2022:15:57:15 -0700] [Client 2867] Accepted from [192.168.1.100:53620](http://192.168.1.100:53620/) (IPv4)
D [13/Oct/2022:15:57:15 -0700] [Client 2867] Waiting for request.
D [13/Oct/2022:15:57:15 -0700] [Client 2867] POST /printers/Brother_HL-2140_series HTTP/1.1

scatterthought avatar Oct 15 '22 20:10 scatterthought

It is kind of weird though that the host field would be set to localhost when the requests are actually being sent to another machine over the network. I think this might be an issue with cups4j instead of this addon though.

Rapti avatar Oct 16 '22 12:10 Rapti

ServerAlias localhost seems to have worked, as I haven't seen any more warnings. Do you want to report an issue on the cups4j Github? I'd do it, but I don't have enough technical knowledge (as evidenced by this discussion).

I'm going to close this issue and post in the openHAB Community in case someone else runs into this. Thanks for your help, @Rapti @wborn!

scatterthought avatar Oct 16 '22 19:10 scatterthought

This issue has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/oh-3-3-ipp-binding-bad-request-error-with-cups/140021/1

openhab-bot avatar Oct 16 '22 19:10 openhab-bot

This issue has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/oh-3-3-ipp-binding-bad-request-error-with-cups/140021/2

openhab-bot avatar Oct 16 '22 19:10 openhab-bot

I think it may be a bug in cups4j. Seems like https://github.com/harwey/cups4j/pull/42 changed with https://github.com/harwey/cups4j/commit/956990c0dbdeb29d521892c5d0b4e5aab5974c07 how the Host: header is set in 0.7.9.

wborn avatar Oct 16 '22 19:10 wborn