Raw socket gets data, but does not send data to printer

[zdohnal]

Describe the bug Printing via raw socket does not work, because file is not sent to the device. This current behavior was seen when using lprint, but probably all PAPPL based printer applications are affected.

To Reproduce Steps to reproduce the behavior:

1. start lprint server with -o server-options=raw-socket
2. install a printer via http://localhost:8000 - Zebra GK420t in my case (driver ZPL, 4inch, 203dpi)
3. check services on mDNS, f.e. via avahi-browse -avrt on Linux:

=     lo IPv4 zebra                                         _pdl-datastream._tcp local
   hostname = [fedora-home.local]
   address = [127.0.0.1]
   port = [9101]
   txt = ["Scan=F" "PaperMax=<legal-A4" "Fax=F" "product=(Zebra ZPL 4-inch/203dpi/Direct-Thermal)" "priority=100" "qtotal=1" "txtvers=1" "Duplex=F" "Color=F" "UUID=cbf40622-39e6-3048-6ec7-0e9171137724" "pdl=image/pwg-raster,image/urf,application/vnd.zebra-zpl,application/vnd.lprint-test,image/jpeg,image/png" "note=" "adminurl=http://fedora-home.local:8000/zebra/" "ty=Zebra ZPL 4-inch/203dpi/Direct-Thermal"]

4. send file via netcat

$ netcat 127.0.0.1 9101 < <zpl file>

5. Nothing is printed

Expected behavior Printer-ready file will be printed

System Information:

• OS: Fedora Linux 39
• Browser Firefox
• lprint 1.2.0
• pappl 1.4.4

Additional context Attaching debug log from lprint and packet capture between my machine and printer - first it is attempt to send the file via lprint raw socket, then, after approx. 10s, I sent the same file directly to the printer via netcat. I can see in the log that the file is sent to the destination in both cases, but no activity after that in lprint case.

lprint.pcap.txt lprint-raw.log.txt

[michaelrsweet]

Try running

netcat fedora-home.local 9101 < ZPL-FILE

It is possible the default listener isn't responding to the loopback interface...

[zdohnal]

Pinging the port via nc worked at that time:

$ nc -vz 127.0.0.1 9101

but I'll recheck.

In the meantime I'm on another machine, but sw versions are the same, but the port differs.

However, the behavior is the same with hostname and non-localhost IP - the port is accessible, wireshark shows the data was sent, but no TCP FIN packet (which makes netcat hang):

$ nc -vz fedora-4.local 9111
Ncat: Version 7.93 ( https://nmap.org/ncat )
Ncat: Connected to <IP>:9111.
Ncat: 0 bytes sent, 0 bytes received in 0.13 seconds.
$ netcat fedora-4.local 9111 < ~/Downloads/file.zpl
^C
$ nc -vz <IP> 9111
Ncat: Version 7.93 ( https://nmap.org/ncat )
Ncat: Connected to <IP>:9111.
Ncat: 0 bytes sent, 0 bytes received in 0.02 seconds.
$ netcat <IP> 9111 < ~/Downloads/rhel9-printserver-rhel8-printclient.zpl
^C
$ nc -vz 127.0.0.1 9111
Ncat: Version 7.93 ( https://nmap.org/ncat )
Ncat: Connected to 127.0.0.1:9111.
Ncat: 0 bytes sent, 0 bytes received in 0.02 seconds.
$ netcat 127.0.0.1 9111 < ~/Downloads/rhel9-printserver-rhel8-printclient.zpl
^C

[michaelrsweet]

OK, I think I know what is going wrong - when the maximum number of active jobs is not set (default), the raw loop doesn't get a chance to accept the connection. Simple fix...

[master 5db71eb] Fix the raw input socket code to not wait indefinitely when max-active-jobs is 0 (Issue #331)

[v1.4.x 3e1524c] Fix the raw input socket code to not wait indefinitely when max-active-jobs is 0 (Issue #331)

[zdohnal]

Unfortunately, it didn't help :( - I heard there was some issues when accessing lower numbered ports, but I don't remember what was the fix - disabling firewall and selinux did not help.

[michaelrsweet]

Unfortunately, it didn't help :( - I heard there was some issues when accessing lower numbered ports, but I don't remember what was the fix - disabling firewall and selinux did not help.

910x isn't a low-numbered ("privileged") port less than 1024. Please collect debug logs and try this with the testpappl program from the PAPPL sources (to isolate issues with a particular printer application).

[zdohnal]

Do you mean debug logs from lprint? Or does pappl have another way of debugging? The current lprint logs are here.

EDIT: Ok, now this is funny :D - netcat looks frozen, but once I kill the process, the file is printed correctly. It looks like a different bug - if I send the file to the real printer, netcat finishes correctly without needing to kill it.

From the log:

 46 Feb 08 17:59:17 fedora lprint[74847]: [Printer zebra-lprint] Accepted socket print connection from IP.
 47 Feb 08 17:59:17 fedora lprint[74847]: [Job 1] Created job file "/tmp/pappl74847.d/p00014j000000001-untitled.prn", format "application/vnd.zebra-zpl".
 48 Feb 08 17:59:27 fedora lprint[74847]: [Printer zebra-lprint] Checking for new jobs to process.
 49 Feb 08 17:59:27 fedora lprint[74847]: [Printer zebra-lprint] Starting job 1.
 50 Feb 08 17:59:27 fedora lprint[74847]: [Job 1] Starting print job.
 51 Feb 08 17:59:27 fedora lprint[74847]: [Job 1] Getting options for num_pages=0, color=false

that 10s is the time frame when I wait whether the netcat finishes.

Looks like lprint is looping here:

163           for (;;)
164           {
165             if (papplPrinterIsDeleted(printer) || !papplSystemIsRunning(printer->system))
166             {
167               bytes = -1;
168               break;
169             }
170 
171             if ((bytes = poll(&sockp, 1, 1000)) < 0)
172             {
173               if ((time(NULL) - activity) >= 60)
174                 break;
175               else
176                 continue;
177             }
178 
179             activity = time(NULL);
180 
181             if (sockp.revents & POLLIN)
182             {
183               if ((bytes = recv(sock, buffer, sizeof(buffer), 0)) > 0)
184                 write(job->fd, buffer, (size_t)bytes);
185               else
186                 break;
187             }
188             else if (sockp.revents & POLLERR)
189             {
190               bytes = -1;
191               break;
192             }
193           }

After file is sent, poll always returns 0 and revents is 0 as well. Probably

171             if ((bytes = poll(&sockp, 1, 1000)) < 0)

should be <= ?

[zdohnal]

For some reason I see bytes being 0, but the execution does not go into true branch even if the condition is <=...

[michaelrsweet]

poll() will return -1 on error, 0 on no data, and 1 on data input. Maybe I need to add a check for POLLHUP?

Try this:

[master e7561fe] Add POLLHUP check in socket reader (Issue #331)

[v1.4.x 93663bc] Add POLLHUP check in socket reader (Issue #331)