Konfiguration
-------------

1 PowerMac Dual 2.5 (10_0_1_10)
- MacOS X 10.3.6
- Drucker Canon I990 ist per USB angeschlossen; Printer-Sharing aktiviert
- Per Ethernet an Airport Extreme Basisstatistion
1 Powerbook Alu 1,25 (10_0_1_11)
- MacOS X 10.3.6
- Per WLAN an internes Netzwerk angeschlossen (in Airport Express eingebucht)
1 Airport Extreme Basisstation (IP: 10_0_1_1)
- Standort: Arbeitszimmer
- Neuestes Firmwareupdate (incl. Airport 4.1)
- Internes Netzwerk ist angeschlossen
- DSL-Modem ist angeschlossen
- WDS-Betrieb mit Airport Express
-- Airport Extreme ist Basisstation
-- Airport Express ist entfernte Station
- Beide Stationen verwenden verschiedene Netzwerknamen. Der Fehler tritt allerdings auch bei gleichen Netzwerknamen auf, wenn das Notebook in der Airport Express Station eingebucht ist. Dies konnte ich durch Standortwechsel nachvollziehen.

1 Airport Express (IP: 10_0_1_2)
- Neuestes Firmwareupdate (incl. Airport 4.1)
- Standort: Wohnzimmer
- WDS-Betrieb (siehe Airport Extreme Basisstation)
- Stereoanlage ist an Airport Express angeschlossen
- PC-Notebook mit Windows ist an Ethernet angeschlossen. Es spielt bei der weiteren Betrachtung aber keine Rolle

Fehlerbeschreibung
------------------
In der beschrieben Konfiguration habe ich Probleme, Drucke vom Powerbook abzusetzen. Im Detail sieht es so aus:

Veranlassen eines Druckes, wobei die Applikation egal ist. Der Fehler tritt in beliebigen Programmen, wie Safari, Word, Vorschau, BBEdit usw. auf. Der empfangene Drucker ist der Canon I990, der am Powermac Dual 2.5 angeschlossen ist.

Der Druckjob wird in der Warteschlange auf dem Powerbook angezeigt. Allerdings lautet die Statusmeldung „retrying print job“. Weiterführende Fehlermeldungen sind auch in der Konsole (system.log, console.log, cups/error.o) auf dem Powerbook nicht enthalten.

Der Druckjob wird nicht auf dem Drucker ausgegeben. Gemäß der Netzwerküberwachung des Programms „netBarrier“ auf dem Powermac Dual 2.5 wird angezeigt, dass eine IPP-Verbindung aufgebaut, kurz danach aber wieder abgebaut wird. Dies wiederholt sich einige Minuten. Dann allerdings erfolgt der Druck. Diese „Wartezeit“ kann wenige Sekunden bis über 10 Minuten betragen. Gemäß „netBarrier“ wird immer wieder eine IPP Verbindung aufgebaut und dann wieder geschlossen.

Zu Testzwecken habe ich die Firewalls auf dem Powerbook und Powermac abgeschaltet. Das Problem blieb aber bestehen.

Vom Powermac Dual kann ich ohne Probleme auf dem Canon I990 ausdrucken (USB).

Im Netzwerk konnte ich ansonsten für folgende Fälle keine Probleme feststellen
- Internetzugang vom Powermac Dual
- Internetzugang vom Powerbook
- Ping vom Powermac zum Powerbook und umgekehrt
- Laufwerke des jeweils anderen Rechners über Netzwerk auf dem Powerbook bzw. Powermac mounten
- Musikstreaming vom Powermac Dual zur Stereoanlage; auf dem Powermac ist die zentrale Musikbibliothek gespeichert. Diese ist für das Netzwerk freigegeben.
- Musikstreaming vom Powerbook zur Stereoanlage; hier wird die Musikbibliothek des Powermac Dual verwendet.
- Interessanterweise ist festzuhalten, dass vereinzelte Druckjobs des Powerbooks ohne Probleme ausgegeben werden. Dies ging in einem Fall sogar soweit, dass ein Druckjob vom nächsten „überholt“ wurde. D.h. der erste Druckjob wurde nicht ausgegeben. Sein Status auf dem Powerbook war „retrying print job“ . Ein danach auf dem Powerbook erzeugter Druck hingegen kam sofort auf dem Drucker heraus.

Maßnahmen zur Fehleranalyse
----------------------------
Zuerst habe ich in der Datei „/etc/cups/cupsd.conf“ die Protokollierung auf dem Powermac Dual in den Debug -2-Modus eingestellt. So konnte ich die Druckjobs vom PowerBook nachvollziehen. Dort zeigte sich, dass der Druckjob auf dem Powermac ankommt, mittendrin allerdings ein senderror (http error code 400) auftritt. Ich habe die Protokolldatei (siehe unten) beigelegt. Meiner Meinung nach tritt der Fehler auf, wenn versucht wird, eine Spooldatei auf dem Zielrechner (PowerMac) anzulegen.

Der Fehler ist weiterhin präsent, wenn ich den Drucker an der Airport Extrem Basisstation anschließe. Darüber hinaus lässt sich der Fehler nachvollziehen, wenn ich den Powermac Dual vom Ethernet Netzwerk trenne und per Airport in Airport Express bzw. Airport Extreme Basisstation einbuche.

ACHTUNG:
Der Fehler verschwindet, wenn ich das Powerbook nicht mehr in der Airport Express, sondern in der Airport Extreme Station eingebucht habe. Hier werden die Drucke des Powerbooks ohne Probleme ausgegeben. Des Weiteren tritt der Fehler nicht auf, wenn ich vom Powerbook aus unter dem Root-Account drucke und in der Airport Express Station eingebucht bin.


Protokoll (suche “ReadClient() 8 IPP Read Error!“)
------------------------------------------
d [02/Oct/2004:09:00:55 +0200] AcceptClient(0x300c90) 0 NumClients = 1
D [02/Oct/2004:09:00:55 +0200] AcceptClient() 8 from 10_0_1_11:631_
d [02/Oct/2004:09:00:55 +0200] AcceptClient: Adding fd 8 to InputSet...
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
D [02/Oct/2004:09:00:55 +0200] ReadClient() 8 POST /printers/i990 HTTP/1_1
d [02/Oct/2004:09:00:55 +0200] decode_auth(0x407a2c): Authorization string = ""
d [02/Oct/2004:09:00:55 +0200] decode_auth() 8 username=""
d [02/Oct/2004:09:00:55 +0200] IsAuthorized: conuri = "/printers/i990"
d [02/Oct/2004:09:00:55 +0200] FindBest: uri = "/printers/i990"...
d [02/Oct/2004:09:00:55 +0200] FindBest: Location CUPS_INTERNAL_BROWSE_ACL Limit 0
d [02/Oct/2004:09:00:55 +0200] FindBest: Location / Limit 7f
d [02/Oct/2004:09:00:55 +0200] FindBest: Location /admin Limit 7f
d [02/Oct/2004:09:00:55 +0200] FindBest: best = "/"
d [02/Oct/2004:09:00:55 +0200] IsAuthorized: auth = 0, satisfy=0_..
d [02/Oct/2004:09:00:55 +0200] POST /printers/i990
d [02/Oct/2004:09:00:55 +0200] CONTENT_TYPE = application/ipp
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 91342, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 91334, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 91305, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 91271, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 91218, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 91189, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 91160, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 91125, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 91105, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 91092, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 91073, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 91057, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 90996, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 90974, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 90913, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 90856, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 90793, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 90736, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 90684, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 90627, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 90570, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 90506, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 90445, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 90382, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 90356, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 90299, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 90244, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 90187, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 90130, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 90072, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 90015, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 89963, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 89906, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 89849, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 89791, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 89730, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 89673, confile = 0
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8, used=51
d [02/Oct/2004:09:00:55 +0200] ReadClient() 8 condata_encoding = length, condata_remaining = 89614, confile = 0
E [02/Oct/2004:09:00:56 +0200] ReadClient() 8 IPP Read Error!
D [02/Oct/2004:09:00:56 +0200] SendError() 8 code=400
d [02/Oct/2004:09:00:56 +0200] ShutdownClient: Removing fd 8 from InputSet...
d [02/Oct/2004:09:00:59 +0200] SendBrowseList: (81 bytes to "en0") f04e 3 [url]ipp://MACVONA.local/printers/AdobePDF[/url] "" "Adobe PDF" "Adobe PDF 3015.102"
d [02/Oct/2004:09:00:59 +0200] UpdateCUPSBrowse: (81 bytes from 10_0_1_10) f04e 3 [url]ipp://MACVONA.local/printers/AdobePDF[/url] "" "Adobe PDF" "Adobe PDF 3015.102"
d [02/Oct/2004:09:01:01 +0200] SendBrowseList: (79 bytes to "en0") 3006 3 [url]ipp://MACVONA.local/printers/Page_Sender[/url] "" "Page Sender" "Page Sender"
d [02/Oct/2004:09:01:01 +0200] UpdateCUPSBrowse: (79 bytes from 10_0_1_10) 3006 3 [url]ipp://MACVONA.local/printers/Page_Sender[/url] "" "Page Sender" "Page Sender"
d [02/Oct/2004:09:01:07 +0200] AcceptClient(0x300c90) 0 NumClients = 2
D [02/Oct/2004:09:01:07 +0200] AcceptClient() 9 from 10_0_1_11:631_
d [02/Oct/2004:09:01:07 +0200] AcceptClient: Adding fd 9 to InputSet...
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9, used=0
D [02/Oct/2004:09:01:07 +0200] ReadClient() 9 POST /printers/i990 HTTP/1_1
d [02/Oct/2004:09:01:07 +0200] decode_auth(0x40a458): Authorization string = ""
d [02/Oct/2004:09:01:07 +0200] decode_auth() 9 username=""
d [02/Oct/2004:09:01:07 +0200] IsAuthorized: conuri = "/printers/i990"
d [02/Oct/2004:09:01:07 +0200] FindBest: uri = "/printers/i990"...
d [02/Oct/2004:09:01:07 +0200] FindBest: Location CUPS_INTERNAL_BROWSE_ACL Limit 0
d [02/Oct/2004:09:01:07 +0200] FindBest: Location / Limit 7f
d [02/Oct/2004:09:01:07 +0200] FindBest: Location /admin Limit 7f
d [02/Oct/2004:09:01:07 +0200] FindBest: best = "/"
d [02/Oct/2004:09:01:07 +0200] IsAuthorized: auth = 0, satisfy=0_..
d [02/Oct/2004:09:01:07 +0200] POST /printers/i990
d [02/Oct/2004:09:01:07 +0200] CONTENT_TYPE = application/ipp
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9 condata_encoding = length, condata_remaining = 91342, confile = 0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9, used=0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9 condata_encoding = length, condata_remaining = 91334, confile = 0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9, used=0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9 condata_encoding = length, condata_remaining = 91305, confile = 0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9, used=0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9 condata_encoding = length, condata_remaining = 91271, confile = 0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9, used=0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9 condata_encoding = length, condata_remaining = 91218, confile = 0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9, used=0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9 condata_encoding = length, condata_remaining = 91189, confile = 0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9, used=0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9 condata_encoding = length, condata_remaining = 91160, confile = 0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9, used=0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9 condata_encoding = length, condata_remaining = 91125, confile = 0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9, used=0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9 condata_encoding = length, condata_remaining = 91105, confile = 0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9, used=0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9 condata_encoding = length, condata_remaining = 91092, confile = 0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9, used=0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9 condata_encoding = length, condata_remaining = 91073, confile = 0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9, used=0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9 condata_encoding = length, condata_remaining = 91057, confile = 0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9, used=0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9 condata_encoding = length, condata_remaining = 90996, confile = 0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9, used=0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9 condata_encoding = length, condata_remaining = 90974, confile = 0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9, used=0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9 condata_encoding = length, condata_remaining = 90913, confile = 0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9, used=0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9 condata_encoding = length, condata_remaining = 90856, confile = 0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9, used=0
d [02/Oct/2004:09:01:07 +0200] ReadClient() 9 condata_encoding = length, condata_remaining = 90793, confile = 0

usw. ...

PS: Der Fehler trat auch schon unter 10.3.5 auf, auch mit den älteren Firmwareversionen der beiden Basisstationen

PPS: Neuestes Firmware Update für die Juni-2004-G5 ist eingespielt. Der Fehler bleibt bestehen.

vielleicht eine dämlich Frage, aber kannst du den Drucker mal einen einen der Airport Stationen anschließen. Vielleicht klappt es dann.

Ansonsten kann ich nur sagen, dass ich auch öfter versuche mittels Printer Sharing zu drucken, und es nicht klappt.

Habe anscheinend ein ähnliches Problem.
Habe seit Freitag eine AEX in mein bestehendes Airport Netzwerk eingebunden mit einer Airport Extreme Station und darin über Ethernet angeschlossenen Farblaser. Wollte gestern das erste Mal drucken und nichts passiert. Die Druckaufträge sind gelistet auf meinem Pismo und Daten werden angeblich übertragen (sending data), aber am Drucker kommt nichts an. Am Drucker leuchtet nur ab und zu das Licht auf, das anzeigt wenn Daten eingehen am Drucker. Es scheint so, dass immer wieder Übertragungsversuche stattfinden.

Pismo mit 10.3.6
Airport Extreme als WDS und QMS-Minolta Magicolor 2+ über Ethernet
Airport Express

Gruss

rofl<br>
<br>Ich hatte den Drucker schon einmal an die AEBS angeschlossen. Dort trat das gleiche Problem auf
<br>
<br><br>
<br>Wenn das Powerbook in der AEBS eingebucht ist, klappt bei mir alles ohne Probleme. Ich hatte den PowerMac sogar vom Ethernet getrennt und über Airport betrieben. Dabei war es egal, ob ich den Powermac in die AEBS oder AX Station einbuchte. Das Problem blieb bestehen.
<br>
<br>