3751 03:19:12.474 ippNewRequest(op=0b(Get-Printer-Attributes)) 4310 03:19:12.484 cupsDoIORequest: setup... 4311 03:19:12.484 cupsSendRequest(http=0xbb52e000, request=0xbb512070(Get-Printer-Attributes), resource="/ipp", length=476) 4480 03:19:12.485 cupsSendRequest: Waiting for 100-continue... 4481 03:19:12.485 _httpWait(http=0xbb52e000, msec=1000, usessl=1) 4482 03:19:12.493 _httpWait: returning with nfds=1... 4483 03:19:12.493 httpUpdate(http=0xbb52e000), state=HTTP_POST_SEND 4484 03:19:12.493 httpGets(line=0xbfbe4e50, length=32768, http=0xbb52e000) 4485 03:19:12.493 httpGets: read 158 bytes... 4486 03:19:12.493 httpGets: Returning "HTTP/1.1 200 OK" 4487 03:19:12.493 httpUpdate: Got "HTTP/1.1 200 OK" 4511 03:19:12.493 cupsDoIORequest: status=200 4512 03:19:12.493 cupsGetResponse(http=0xbb52e000, resource="/ipp") 4513 03:19:12.493 cupsGetResponse: Finishing chunked POST... 4514 03:19:12.493 httpWrite2(http=0xbb52e000, buffer=0xbbbcbaf5, length=0) 4515 03:19:12.493 httpWrite: changing states... 4516 03:19:12.493 http_write: 5 bytes: 4517 03:19:12.493 http_write: 300D0A0D0A 0.... 4518 03:19:12.493 cupsGetResponse: Update loop, http->status=200... 4519 03:19:12.493 cupsGetResponse: status=200 4520 03:19:12.493 ippNew() 4521 03:19:12.493 ippNew: Returning 0xbb512190 4522 03:19:12.493 ippRead(http=0xbb52e000, ipp=0xbb512190), data_remaining=0 4523 03:19:12.493 ippRead: http->state=0, http->used=0 4524 03:19:12.493 ippReadIO(src=0xbb52e000, cb=0xbbbb04e0, blocking=1, parent=0x0, ipp=0xbb512190) 4525 03:19:12.493 ippReadIO: ipp->state=0 4526 03:19:12.493 ipp_read_http(http=0xbb52e000, buffer=0xbb534000, length=8) 4527 03:19:12.493 ipp_read_http: tbytes=0, http->state=0 4528 03:19:12.493 ipp_read_http: Returning 0 bytes 4529 03:19:12.493 ippReadIO: Unable to read header! 4530 03:19:12.493 cupsGetResponse: IPP read error! 4531 03:19:12.493 ippDelete(ipp=0xbb512190) 4532 03:19:12.493 _cupsSetError: last_error=server-error-service-unavailable, last_status_message="(null)" 4533 03:19:12.493 cupsDoIORequest: status=200 4534 03:19:12.493 cupsDoIORequest: setup... 4535 03:19:12.493 cupsSendRequest(http=0xbb52e000, request=0xbb512070(Get-Printer-Attributes), resource="/ipp", length=476) 4544 03:19:12.493 cupsSendRequest: Sending HTTP POST... 4704 03:19:12.505 cupsSendRequest: Waiting for 100-continue... 4705 03:19:12.505 _httpWait(http=0xbb52e000, msec=1000, usessl=1) 4706 03:19:12.505 _httpWait: returning with nfds=1... 4707 03:19:12.505 httpUpdate(http=0xbb52e000), state=HTTP_POST_SEND 4708 03:19:12.505 httpGets(line=0xbfbe4e50, length=32768, http=0xbb52e000) 4709 03:19:12.505 httpGets: read 642 bytes... 4710 03:19:12.505 httpGets: Returning "276" 4711 03:19:12.505 httpUpdate: Got "276" 4712 03:19:12.505 httpUpdate: Bad response line "276"! 4713 03:19:12.505 cupsSendRequest: status=-1 4714 03:19:12.505 cupsDoIORequest: status=-1 4715 03:19:12.505 httpFlush(http=0xbb52e000), state=HTTP_POST_SEND 4716 03:19:12.505 httpRead2(http=0xbb52e000, buffer=0xbfbeaebc, length=8192) 4717 03:19:12.505 httpRead2: data_remaining=0 4718 03:19:12.505 cupsDoIORequest: status=-1 4719 03:19:12.505 _cupsSetHTTPError: HTTP error -1 mapped to IPP_SERVICE_UNAVAILABLE! 4948 WARNING: recoverable: Network host 'co256-copier.ecs.vuw.ac.nz' is busy; will retry in 5 seconds... 4953 03:19:17.515 ippNewRequest(op=0b(Get-Printer-Attributes)) 5541 03:19:17.526 cupsDoIORequest: setup... 5542 03:19:17.526 cupsSendRequest(http=0xbb52e000, request=0xbb512070(Get-Printer-Attributes), resource="/ipp", length=476) 5549 03:19:17.526 cupsSendRequest: Setup... 5550 03:19:17.526 cupsSendRequest: authstring="(null)" 5551 03:19:17.526 cupsSendRequest: Sending HTTP POST... 5552 03:19:17.526 http_send(http=0xbb52e000, request=HTTP_POST, uri="/ipp") 5553 03:19:17.526 httpReconnect(http=0xbb52e000) 5554 03:19:17.526 httpReconnect: Closing socket 5... 5564 03:19:17.526 httpAddrConnect: Connected to 130.195.6.249:631... 5565 03:19:17.526 httpReconnect: New socket=5 5727 03:19:17.527 cupsSendRequest: Waiting for 100-continue... 5728 03:19:17.527 httpUpdate(http=0xbb52e000), state=HTTP_POST_SEND 5729 03:19:17.527 httpGets(line=0xbfbe4e50, length=32768, http=0xbb52e000) 5730 03:19:17.527 httpGets: Returning "\001\001" 5731 03:19:17.527 httpUpdate: Got "\001\001" 5732 03:19:17.527 httpUpdate: Bad response line "\001\001"! 5733 03:19:17.527 cupsSendRequest: status=-1 5734 03:19:17.527 cupsDoIORequest: status=-1 5735 03:19:17.527 httpFlush(http=0xbb52e000), state=HTTP_POST_SEND 5736 03:19:17.527 httpRead2(http=0xbb52e000, buffer=0xbfbeaebc, length=8192) 5737 03:19:17.527 httpRead2: data_remaining=0 5738 03:19:17.527 cupsDoIORequest: status=-1 5739 03:19:17.527 _cupsSetHTTPError: HTTP error -1 mapped to IPP_SERVICE_UNAVAILABLE! 5978 WARNING: recoverable: Network host 'co256-copier.ecs.vuw.ac.nz' is busy; will retry in 10 seconds... 5983 03:19:27.538 ippNewRequest(op=0b(Get-Printer-Attributes)) 6571 03:19:27.549 cupsDoIORequest: setup... 6572 03:19:27.549 cupsSendRequest(http=0xbb52e000, request=0xbb512070(Get-Printer-Attributes), resource="/ipp", length=476) 6579 03:19:27.549 cupsSendRequest: Setup... 6580 03:19:27.549 cupsSendRequest: authstring="(null)" 6581 03:19:27.549 cupsSendRequest: Sending HTTP POST... 6582 03:19:27.549 http_send(http=0xbb52e000, request=HTTP_POST, uri="/ipp") 6583 03:19:27.549 httpReconnect(http=0xbb52e000) 6584 03:19:27.549 httpReconnect: Closing socket 5... 6594 03:19:27.550 httpAddrConnect: Connected to 130.195.6.249:631... 6595 03:19:27.550 httpReconnect: New socket=5 6758 03:19:27.550 httpUpdate(http=0xbb52e000), state=HTTP_POST_SEND 6758 03:19:27.550 httpGets(line=0xbfbe4e50, length=32768, http=0xbb52e000) 6760 03:19:27.550 httpGets: Returning "image/tiffI" 6761 03:19:27.550 httpUpdate: Got "image/tiffI" 6762 03:19:27.550 httpUpdate: Bad response line "image/tiffI"! 6763 03:19:27.550 cupsSendRequest: status=-1 6764 03:19:27.550 cupsDoIORequest: status=-1 6765 03:19:27.550 httpFlush(http=0xbb52e000), state=HTTP_POST_SEND 6766 03:19:27.550 httpRead2(http=0xbb52e000, buffer=0xbfbeaebc, length=8192) 6767 03:19:27.550 httpRead2: data_remaining=0 6768 03:19:27.550 cupsDoIORequest: status=-1 6769 03:19:27.550 _cupsSetHTTPError: HTTP error -1 mapped to IPP_SERVICE_UNAVAILABLE! 7008 WARNING: recoverable: Network host 'co256-copier.ecs.vuw.ac.nz' is busy; will retry in 15 seconds... 7013 03:19:42.563 ippNewRequest(op=0b(Get-Printer-Attributes)) 7601 03:19:42.574 cupsDoIORequest: setup... 7602 03:19:42.574 cupsSendRequest(http=0xbb52e000, request=0xbb512070(Get-Printer-Attributes), resource="/ipp", length=476) 7609 03:19:42.574 cupsSendRequest: Setup... 7610 03:19:42.574 cupsSendRequest: authstring="(null)" 7611 03:19:42.574 cupsSendRequest: Sending HTTP POST... 7612 03:19:42.574 http_send(http=0xbb52e000, request=HTTP_POST, uri="/ipp") 7613 03:19:42.574 httpReconnect(http=0xbb52e000) 7614 03:19:42.574 httpReconnect: Closing socket 5... 7624 03:19:42.575 httpAddrConnect: Connected to 130.195.6.249:631... 7625 03:19:42.575 httpReconnect: New socket=5 7787 03:19:42.576 cupsSendRequest: Waiting for 100-continue... 7788 03:19:42.576 httpUpdate(http=0xbb52e000), state=HTTP_POST_SEND 7789 03:19:42.576 httpGets(line=0xbfbe4e50, length=32768, http=0xbb52e000) 7790 03:19:42.576 httpGets: Returning "image/jpegI" 7791 03:19:42.576 httpUpdate: Got "image/jpegI" 7792 03:19:42.576 httpUpdate: Bad response line "image/jpegI"! 7793 03:19:42.576 cupsSendRequest: status=-1 7794 03:19:42.576 cupsDoIORequest: status=-1 7795 03:19:42.576 httpFlush(http=0xbb52e000), state=HTTP_POST_SEND 7796 03:19:42.576 httpRead2(http=0xbb52e000, buffer=0xbfbeaebc, length=8192) 7797 03:19:42.576 httpRead2: data_remaining=0 7798 03:19:42.576 cupsDoIORequest: status=-1 7799 03:19:42.576 _cupsSetHTTPError: HTTP error -1 mapped to IPP_SERVICE_UNAVAILABLE! 8038 WARNING: recoverable: Network host 'co256-copier.ecs.vuw.ac.nz' is busy; will retry in 20 seconds... 8043 03:20:02.591 ippNewRequest(op=0b(Get-Printer-Attributes)) 8822 03:20:02.603 httpUpdate: Bad response line "image/jpeg\""! 9068 WARNING: recoverable: Network host 'co256-copier.ecs.vuw.ac.nz' is busy; will retry in 25 seconds... 9073 03:20:27.619 ippNewRequest(op=0b(Get-Printer-Attributes)) 9852 03:20:27.631 httpUpdate: Bad response line "0"! 10098 WARNING: recoverable: Network host 'co256-copier.ecs.vuw.ac.nz' is busy; will retry in 30 seconds... 10103 03:20:57.649 ippNewRequest(op=0b(Get-Printer-Attributes)) 10691 03:20:57.660 cupsDoIORequest: setup... 10692 03:20:57.660 cupsSendRequest(http=0xbb52e000, request=0xbb512070(Get-Printer-Attributes), resource="/ipp", length=476) 10877 03:20:57.661 cupsSendRequest: Waiting for 100-continue... 10878 03:20:57.661 httpUpdate(http=0xbb52e000), state=HTTP_POST_SEND 10879 03:20:57.661 httpGets(line=0xbfbe4e50, length=32768, http=0xbb52e000) 10880 03:20:57.661 httpGets: Returning "" 10881 03:20:57.661 httpUpdate: Got "" 10882 03:20:57.661 cupsSendRequest: status=100 10883 03:20:57.661 cupsDoIORequest: status=100 10884 03:20:57.661 cupsGetResponse(http=0xbb52e000, resource="/ipp") 10885 03:20:57.661 cupsGetResponse: Update loop, http->status=100... 10886 03:20:57.661 httpUpdate(http=0xbb52e000), state=HTTP_POST_SEND 10887 03:20:57.661 httpGets(line=0xbfbe4e80, length=32768, http=0xbb52e000) 10888 03:20:57.670 httpGets: read 158 bytes... 10889 03:20:57.670 httpGets: Returning "HTTP/1.1 200 OK" 10890 03:20:57.670 httpUpdate: Got "HTTP/1.1 200 OK" 12882 03:20:57.923 ippFindAttribute: attr=0xbb51e300, name="printer-state" 12883 03:20:57.923 ippFindAttribute: attr=0xbb51e320, name="printer-state-reasons" 12884 03:20:57.923 ippFindAttribute: attr=0xbb53d1e0, name="document-format-supported" 12885 03:20:57.923 ippFindAttribute: attr=0xbb51e440, name="printer-is-accepting-jobs" 12886 03:20:57.923 ippFindAttribute(ipp=0xbb512190, name="marker-types", type=44(keyword)) 12887 03:20:57.930 ippFindNextAttribute(ipp=0xbb512190, name="marker-types", type=44(keyword)) 12888 03:20:57.930 ippFindAttribute: attr=0xbb51e2a0, name="attributes-charset" 12889 03:20:57.930 ippFindAttribute: attr=0xbb51e2c0, name="attributes-natural-language" 12890 03:20:57.930 ippFindAttribute: attr=0xbb53d100, name="requested-attributes" 12891 03:20:57.930 ippFindAttribute: attr=0xbb51e2e0, name="copies-supported" 12892 03:20:57.930 ippFindAttribute: attr=0xbb51e300, name="printer-state" 12893 03:20:57.930 ippFindAttribute: attr=0xbb51e320, name="printer-state-reasons" 12894 03:20:57.930 ippFindAttribute: attr=0xbb53d1e0, name="document-format-supported" 12895 03:20:57.930 ippFindAttribute: attr=0xbb51e440, name="printer-is-accepting-jobs" 12896 INFO: recovered: 12897 03:21:02.941 cupsSideChannelRead(command=0xbfbf4f58, status=0xbfbf4f54, data=0xbfbf3910, datalen=0xbfbf4f50(2048), timeout=1.000) 12898 03:21:02.941 cupsSideChannelRead: Short read of 0 bytes 12899 03:21:02.941 ippNewRequest(op=02(Print-Job))