search

alexpevzner / sane-airscan

Scanner Access Now Easy - universal driver for eSCL (Apple AirScan) and WSD
Other
289 stars 44 forks source link

airscan crashed if some device(s) were added in the airscan.conf #83

Closed tangyanli closed 4 years ago

tangyanli commented 4 years ago

Hi, Alexander

I updated the airscan to version 0.99.17 today. The xsane/simple-scan crashed if I added some device(s) in the airscan.conf file. Below is the call stack. And do you need more log files?

Thread 1 "xsane" received signal SIGSEGV, Segmentation fault. __strcasecmp_l_avx () at ../sysdeps/x86_64/multiarch/strcmp-sse42.S:200 200 ../sysdeps/x86_64/multiarch/strcmp-sse42.S: No such file or directory. (gdb) bt

0 __strcasecmp_l_avx () at ../sysdeps/x86_64/multiarch/strcmp-sse42.S:200

1 0x00007ffff29e0ac9 in zeroconf_find_static_by_name (name=0x0) at airscan-zeroconf.c:736

2 zeroconf_device_list_get () at airscan-zeroconf.c:1067

3 0x00007ffff29d16f6 in sane_get_devices (local_only=0, device_list=0x7fffffff9bf0) at airscan.c:66

4 sane_get_devices (device_list=0x7fffffff9bf0, local_only=) at /usr/include/sane/sane.h:221

5 0x00007ffff7f9e1ea in sane_dll_get_devices () at /lib/x86_64-linux-gnu/libsane.so.1

6 0x00005555555e1f6c in ()

7 0x00005555555e7fbe in xsane_interface ()

8 0x0000555555577a76 in main ()

(gdb)

tangyanli commented 4 years ago

PS. The [device] section in the airscan.conf is as below:

[devices]

"Kyocera MFP Scanner" = http://192.168.1.102:9095/eSCL

"Some Unwanted Scanner" = disable

Canon MF745C/746 = http://172.16.9.44:80/eSCL/, eSCL

alexpevzner commented 4 years ago

Hi Tess,

glad to hear from you!

May I see your ~/airscan/trace/xsane-zeroconf.log or ~/airscan/trace/simple-scan-zeroconf.log file after the crash?

tangyanli commented 4 years ago

At this moment, I have tried many times and surprised to find this issue cannot be reproduced any more. I am really sorry for that.

This morning, when I found this issue, I did below test: (1) Degraded to version 0.99.16, added device in the airscan.conf, the issue cannot be reproduced. (2) Upgraded to 0.99.17 again, the issue can be reproduced. (3) Remove the device from airscan.conf, the issue cannot be reproduced.

I will try again on next monday, hope I can reproduce it.

tangyanli commented 4 years ago

I debug the zeroconf_device_name(). One device data is as below, so the zeroconf_device_name() return null.

(gdb) p *device
$12 = {
  devid = 7,
  uuid = {
    text = "urn:uuid:6d4ff0ce-6b11-11d8-8020-f80d609c8532"
  },
  addrs = 0x7fffec004808,
  mdns_name = 0x0,
  model = 0x0,
  protocols = 0,
  methods = 0,
  node_list = {
    ll_prev = 0x7fffec011b50,
    ll_next = 0x7fffec0151f0
  },
  findings = {
    node = {
      ll_prev = 0x7fffec012f90,
      ll_next = 0x7fffec012f90
    }
  },
  buddy = 0x0
}
tangyanli commented 4 years ago

xsane-zeroconf.log records the information about "urn:uuid:6d4ff0ce-6b11-11d8-8020-f80d609c8532" as below. Hope the information is helpful. If not, I can do further debug.

POST http://172.16.9.123/StableWSDiscoveryEndpoint/schemas-xmlsoap-org_ws_2005_04_discovery
Connection: close
Content-Type: application/soap+xml; charset=utf-8
Host: 172.16.9.123
Content-Length: 562

<s:Envelope xmlns:a="http://schemas.xmlsoap.org/ws/2004/08/addressing" xmlns:d="http://schemas.xmlsoap.org/ws/2005/04/discovery" xmlns:s="http://www.w3.org/2003/05/soap-envelope" xmlns:wsdp="http://schemas.xmlsoap.org/ws/2006/02/devprof">
  <s:Header>
    <a:Action>http://schemas.xmlsoap.org/ws/2005/04/discovery/Probe</a:Action>
    <a:MessageID>urn:uuid:29b743c7-f91d-8d4f-c890-517686b29e26</a:MessageID>
    <a:To>urn:schemas-xmlsoap-org:ws:2005:04:discovery</a:To>
  </s:Header>
  <s:Body>
    <d:Probe>
      <d:Types>wsdp:Device</d:Types>
    </d:Probe>
  </s:Body>
</s:Envelope>

Status: 200 OK
Date: Thu, 13 Feb 2020 08:29:43 GMT
Server: CANON HTTP Server
Content-Type: application/soap+xml; charset="utf-8"
Content-Length: 1382

<s:Envelope xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:s="http://www.w3.org/2003/05/soap-envelope">
  <s:Header xmlns:a="http://schemas.xmlsoap.org/ws/2004/08/addressing" xmlns:d="http://schemas.xmlsoap.org/ws/2005/04/discovery">
    <a:Action>http://schemas.xmlsoap.org/ws/2005/04/discovery/ProbeMatches</a:Action>
    <a:MessageID>urn:uuid:fc69324d-4e3a-11ea-8000-f80d609c8532</a:MessageID>
    <a:RelatesTo>urn:uuid:29b743c7-f91d-8d4f-c890-517686b29e26</a:RelatesTo>
    <a:To>http://schemas.xmlsoap.org/ws/2004/08/addressing/role/anonymous</a:To>
    <d:AppSequence InstanceId="370" MessageNumber="722"/>
  </s:Header>
  <s:Body xmlns:d="http://schemas.xmlsoap.org/ws/2005/04/discovery">
    <d:ProbeMatches>
      <d:ProbeMatch xmlns:a="http://schemas.xmlsoap.org/ws/2004/08/addressing">
        <a:EndpointReference>
          <a:Address>urn:uuid:6d4ff0ce-6b11-11d8-8020-f80d609c8532</a:Address>
        </a:EndpointReference>
        <d:Types xmlns:wsdp="http://schemas.xmlsoap.org/ws/2006/02/devprof" xmlns:ns1="http://schemas.microsoft.com/windows/2006/08/wdp/print" xmlns:ns2="http://www.canon.com/ns/active/wsd">wsdp:Device ns1:PrintDeviceType ns2:MFP</d:Types>
        <d:XAddrs>http://172.16.9.123:80/wsd/mex</d:XAddrs>
        <d:MetadataVersion>16</d:MetadataVersion>
      </d:ProbeMatch>
    </d:ProbeMatches>
  </s:Body>
</s:Envelope>

00:00:00.035: WSDD: HTTP POST http://172.16.9.123/StableWSDiscoveryEndpoint/schemas-xmlsoap-org_ws_2005_04_discovery: OK
00:00:00.035: WSDD: ProbeMatches message received from HTTP:
00:00:00.036: WSDD:   address:    urn:uuid:6d4ff0ce-6b11-11d8-8020-f80d609c8532
00:00:00.036: WSDD:   is_scanner: no
00:00:00.036: WSDD:   is_printer: yes
00:00:00.036: WSDD:   xaddr:      http://172.16.9.123:80/wsd/mex
00:00:00.036: zeroconf: found urn:uuid:6d4ff0ce-6b11-11d8-8020-f80d609c8532
00:00:00.036: zeroconf:   method:    ZEROCONF_WSD
00:00:00.036: zeroconf:   interface: 2 (ens33)
00:00:00.036: zeroconf:   name:      -
00:00:00.036: zeroconf:   model:     (null)
00:00:00.036: zeroconf:   addresses:
00:00:00.036: zeroconf:   protocol:  WSD
00:00:00.036: zeroconf:   endpoints:
00:00:00.036: zeroconf:   device:    0008 (created)

00:00:00.036: zeroconf: device_list wait: DNS-SD not finished...
00:00:00.037: WSDD: HTTP POST http://172.16.9.113/StableWSDiscoveryEndpoint/schemas-xmlsoap-org_ws_2005_04_discovery: got response headers (200)
00:00:00.038: WSDD: HTTP POST http://172.16.9.113/StableWSDiscoveryEndpoint/schemas-xmlsoap-org_ws_2005_04_discovery: 200 OK
alexpevzner commented 4 years ago

This is Probe/ProbeMatches exchange.

There must be the second exchange: 

Request: <a:Action>http://schemas.xmlsoap.org/ws/2004/09/transfer/Get</a:Action>
Response: <addressing:Action>http://schemas.xmlsoap.org/ws/2004/09/transfer/GetResponse</addressing:Action>

Note, instead of "addressing" in response there may be "wsa" or something else, it's not important. Search by the word GetResponse

tangyanli commented 4 years ago

I searched the both 0.99.16 and 0.99.17's zeroconf.log files. There is no second exchange...

alexpevzner commented 4 years ago

Seems that I've got it! Please, test.

I guess, 172.16.9.123 is neither printer nor scanner, correct?

alexpevzner commented 4 years ago

Please note, there are 2 patches (was in hurry, my mistake)

tangyanli commented 4 years ago

In my memory, 172.16.9.123 is iR-ADV 4545/4551. I used it to test both eSCL and WSD mode. I will reply you after I check the 172.16.9.123 status and test the new code.

tangyanli commented 4 years ago

Hi, Alexander

This issue is fixed. The ip 172.16.9.123 is configured for device iR-ADV4545/4551, and the device status is: eSCL protocol is enable, WSD protocol is only only for printer (Use WSD Scan Function is set off).

I guess, 172.16.9.123 is neither printer nor scanner, correct?

So the answer is "No".

I picked up all iR-ADV4545/4551 information from 0.99.17's zeroconf.log file.

00:00:00.015: WSDD: directed probe: trying if=ens33, addr=172.16.9.123
00:00:00.015: WSDD: HTTP POST http://172.16.9.123/StableWSDiscoveryEndpoint/schemas-xmlsoap-org_ws_2005_04_discovery
00:00:00.015: WSDD: HTTP resolving 172.16.9.123 80
00:00:00.015: WSDD: HTTP trying 172.16.9.123:80
00:00:00.017: MDNS: resolve/ipv4 "Canon iR-ADV 4545/4551 (9c:85:32) (2)": AVAHI_RESOLVER_FOUND _ipps._tcp
00:00:00.017: WSDD: directed probe: trying if=ens33, addr=172.16.9.123
00:00:00.021: zeroconf: found urn:uuid:0fabc07e-30fd-391d-4bbb-00a953485c6d
00:00:00.021: zeroconf:   method:    ZEROCONF_USCAN_TCP
00:00:00.021: zeroconf:   interface: 2 (ens33)
00:00:00.021: zeroconf:   name:      Canon iR-ADV 4545/4551 (9c:85:32) (2)
00:00:00.021: zeroconf:   model:     Canon iR-ADV 4545/4551
00:00:00.021: zeroconf:   addresses:
00:00:00.021: zeroconf:     172.16.9.123
00:00:00.021: zeroconf:   protocol:  eSCL
00:00:00.021: zeroconf:   endpoints:
00:00:00.021: zeroconf:     http://172.16.9.123:80/eSCL/
00:00:00.021: zeroconf:   device:    0003 (created)
00:00:00.021: WSDD: directed probe: trying if=ens33, addr=172.16.9.123
00:00:00.026: WSDD: HTTP POST http://172.16.9.123/StableWSDiscoveryEndpoint/schemas-xmlsoap-org_ws_2005_04_discovery: 200 OK
==============================
POST http://172.16.9.123/StableWSDiscoveryEndpoint/schemas-xmlsoap-org_ws_2005_04_discovery
Connection: close
Content-Type: application/soap+xml; charset=utf-8
Host: 172.16.9.123
Content-Length: 562

<s:Envelope xmlns:a="http://schemas.xmlsoap.org/ws/2004/08/addressing" xmlns:d="http://schemas.xmlsoap.org/ws/2005/04/discovery" xmlns:s="http://www.w3.org/2003/05/soap-envelope" xmlns:wsdp="http://schemas.xmlsoap.org/ws/2006/02/devprof">
  <s:Header>
    <a:Action>http://schemas.xmlsoap.org/ws/2005/04/discovery/Probe</a:Action>
    <a:MessageID>urn:uuid:cd70ca15-2db6-afc4-069a-7084f528943e</a:MessageID>
    <a:To>urn:schemas-xmlsoap-org:ws:2005:04:discovery</a:To>
  </s:Header>
  <s:Body>
    <d:Probe>
      <d:Types>wsdp:Device</d:Types>
    </d:Probe>
  </s:Body>
</s:Envelope>

Status: 200 OK
Date: Fri, 14 Feb 2020 00:51:33 GMT
Server: CANON HTTP Server
Content-Type: application/soap+xml; charset="utf-8"
Content-Length: 1381

<s:Envelope xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:s="http://www.w3.org/2003/05/soap-envelope">
  <s:Header xmlns:a="http://schemas.xmlsoap.org/ws/2004/08/addressing" xmlns:d="http://schemas.xmlsoap.org/ws/2005/04/discovery">
    <a:Action>http://schemas.xmlsoap.org/ws/2005/04/discovery/ProbeMatches</a:Action>
    <a:MessageID>urn:uuid:259caa50-4ec4-11ea-8000-f80d609c8532</a:MessageID>
    <a:RelatesTo>urn:uuid:cd70ca15-2db6-afc4-069a-7084f528943e</a:RelatesTo>
    <a:To>http://schemas.xmlsoap.org/ws/2004/08/addressing/role/anonymous</a:To>
    <d:AppSequence InstanceId="371" MessageNumber="12"/>
  </s:Header>
  <s:Body xmlns:d="http://schemas.xmlsoap.org/ws/2005/04/discovery">
    <d:ProbeMatches>
      <d:ProbeMatch xmlns:a="http://schemas.xmlsoap.org/ws/2004/08/addressing">
        <a:EndpointReference>
          <a:Address>urn:uuid:6d4ff0ce-6b11-11d8-8020-f80d609c8532</a:Address>
        </a:EndpointReference>
        <d:Types xmlns:wsdp="http://schemas.xmlsoap.org/ws/2006/02/devprof" xmlns:ns1="http://schemas.microsoft.com/windows/2006/08/wdp/print" xmlns:ns2="http://www.canon.com/ns/active/wsd">wsdp:Device ns1:PrintDeviceType ns2:MFP</d:Types>
        <d:XAddrs>http://172.16.9.123:80/wsd/mex</d:XAddrs>
        <d:MetadataVersion>16</d:MetadataVersion>
      </d:ProbeMatch>
    </d:ProbeMatches>
  </s:Body>
</s:Envelope>

00:00:00.026: WSDD: HTTP POST http://172.16.9.123/StableWSDiscoveryEndpoint/schemas-xmlsoap-org_ws_2005_04_discovery: OK
00:00:00.026: WSDD: ProbeMatches message received from HTTP:
00:00:00.026: WSDD:   address:    urn:uuid:6d4ff0ce-6b11-11d8-8020-f80d609c8532
00:00:00.026: WSDD:   is_scanner: no
00:00:00.026: WSDD:   is_printer: yes
00:00:00.026: WSDD:   xaddr:      http://172.16.9.123:80/wsd/mex
00:00:00.026: zeroconf: found urn:uuid:6d4ff0ce-6b11-11d8-8020-f80d609c8532
00:00:00.026: zeroconf:   method:    ZEROCONF_WSD
00:00:00.026: zeroconf:   interface: 2 (ens33)
00:00:00.026: zeroconf:   name:      -
00:00:00.026: zeroconf:   model:     (null)
00:00:00.026: zeroconf:   addresses:
00:00:00.026: zeroconf:   protocol:  WSD
00:00:00.026: zeroconf:   endpoints:
00:00:00.026: zeroconf:   device:    0005 (created)

00:00:02.533: zeroconf: (null) (5): can: none, use: none

tangyanli commented 4 years ago

After fixing, the iR-ADV4545/4551 information in the zeroconf.log are almost same as the 0.99.17's. Except the last one becomes 

00:00:03.220: zeroconf: urn:uuid:6d4ff0ce-6b11-11d8-8020-f80d609c8532 (4): can: none, use: none
00:00:03.220: zeroconf: urn:uuid:6d4ff0ce-6b11-11d8-8020-f80d609c8532 (4): skipping, none of supported protocols discovered
tangyanli commented 4 years ago

If you get the real reason of this issue, can you explain to me :-)

tangyanli commented 4 years ago

BTW I found another issue. This seems little problem, but I cannot get the reason. Below is call stack.

API: sane_close(): done

Thread 1 "xsane" received signal SIGSEGV, Segmentation fault.
0x00007ffff73e92b4 in __GI__IO_default_xsputn (n=<optimised out>, data=<optimised out>, f=<optimised out>) at genops.c:394
394 genops.c: No such file or directory.
(gdb) bt
#0  0x00007ffff73e92b4 in __GI__IO_default_xsputn (n=<optimised out>, data=<optimised out>, f=<optimised out>) at genops.c:394
#1  __GI__IO_default_xsputn (f=f@entry=0x555555669000, data=<optimised out>, n=n@entry=12) at genops.c:370
#2  0x00007ffff73e687a in _IO_new_file_xsputn (n=12, data=<optimised out>, f=<optimised out>) at fileops.c:1265
#3  _IO_new_file_xsputn (f=0x555555669000, data=<optimised out>, n=12) at fileops.c:1197
#4  0x00007ffff73ce27c in __vfprintf_internal
    (s=0x555555669000, format=format@entry=0x7fffef9d00bb "%s: %s", ap=ap@entry=0x7fffffffbd60, mode_flags=mode_flags@entry=2)
    at ../libio/libioP.h:948
#5  0x00007ffff748507c in ___vfprintf_chk
    (fp=<optimised out>, flag=flag@entry=1, format=format@entry=0x7fffef9d00bb "%s: %s", ap=ap@entry=0x7fffffffbd60)
    at vfprintf_chk.c:29
#6  0x00007fffef9ba05d in vfprintf (__ap=0x7fffffffbd60, __fmt=<optimised out>, __stream=<optimised out>)
    at /usr/include/x86_64-linux-gnu/bits/stdio2.h:130
#7  trace_printf (t=t@entry=0x5555558e5488, fmt=fmt@entry=0x7fffef9d00bb "%s: %s") at airscan-trace.c:351
#8  0x00007fffef9ae074 in log_message
    (log=<optimised out>, trace_only=trace_only@entry=false, force=force@entry=false, fmt=<optimised out>, ap=ap@entry=0x7fffffffcf00) at airscan-log.c:200
#9  0x00007fffef9ae562 in log_debug (log=<optimised out>, fmt=<optimised out>) at airscan-log.c:214
#10 0x00007ffff7f9e949 in sane_dll_close () at /lib/x86_64-linux-gnu/libsane.so.1
#11 0x00005555555da9d8 in  ()
#12 0x00005555555e2ecc in  ()
#13 0x00007ffff7bf2b9b in  () at /lib/x86_64-linux-gnu/libgtk-x11-2.0.so.0
#14 0x00007ffff79ae802 in g_closure_invoke () at /lib/x86_64-linux-gnu/libgobject-2.0.so.0
#15 0x00007ffff79c2814 in  () at /lib/x86_64-linux-gnu/libgobject-2.0.so.0
#16 0x00007ffff79cd45d in g_signal_emit_valist () at /lib/x86_64-linux-gnu/libgobject-2.0.so.0
#17 0x00007ffff79ce0d3 in g_signal_emit () at /lib/x86_64-linux-gnu/libgobject-2.0.so.0
#18 0x00007ffff7d0e22d in  () at /lib/x86_64-linux-gnu/libgtk-x11-2.0.so.0
#19 0x00007ffff7bf136b in gtk_main_do_event () at /lib/x86_64-linux-gnu/libgtk-x11-2.0.so.0
#20 0x00007ffff7a596d0 in  () at /lib/x86_64-linux-gnu/libgdk-x11-2.0.so.0
#21 0x00007ffff78c0fbd in g_main_context_dispatch () at /lib/x86_64-linux-gnu/libglib-2.0.so.0
--Type <RET> for more, q to quit, c to continue without paging--
#22 0x00007ffff78c1240 in  () at /lib/x86_64-linux-gnu/libglib-2.0.so.0
#23 0x00007ffff78c1533 in g_main_loop_run () at /lib/x86_64-linux-gnu/libglib-2.0.so.0
#24 0x00007ffff7bf0092 in gtk_main () at /lib/x86_64-linux-gnu/libgtk-x11-2.0.so.0
#25 0x00005555555e7e13 in  ()
#26 0x0000555555577a76 in main ()
tangyanli commented 4 years ago

This is Probe/ProbeMatches exchange.

There must be the second exchange:

Request: <a:Action>http://schemas.xmlsoap.org/ws/2004/09/transfer/Get</a:Action>
Response: <addressing:Action>http://schemas.xmlsoap.org/ws/2004/09/transfer/GetResponse</addressing:Action>

Note, instead of "addressing" in response there may be "wsa" or something else, it's not important. Search by the word GetResponse

I did more test, and get below conclusion, is it correct? If one device's "Use WSD Scan Function" is set off, there is only Probe/ProbeMatches exchange with this device. If one device's "Use WSD Scan Function" is set on, there are Probe/ProbeMatches and Get/GetResponse exchange with this device.

alexpevzner commented 4 years ago

I found another issue. This seems little problem, but I cannot get the reason.

Thanks! I believe I've fixed it.

If one device's "Use WSD Scan Function" is set off, there is only Probe/ProbeMatches exchange with this device.

Yes, exactly. Probe/ProbeMatches exchange brings minimal knowledge about device itself (device exist, it is/is not printer/scanner etc, HTTP endpoints for metadata query).

Get/GetResponse brings device metadata: it's name, model, and HTTP endpoints for particular functions (printing/scanning etc).

If from Probe/ProbeMatches exchange I know device isn't scanner, I suppress Get/GetResponse exchange for optimization reasons (I don't need this data anyway). However, even these devices, known not to implement scanner functionality, are saved to my tables, so higher-level algorithms know, that device is discovered, though it is not WSD scanner, so it doesn't make sense to wait anymore for its discovery completion.

The mistake was to assume that model is always non-NULL: for these "partially discovered" devices model is NULL. It's not a problem by itself, because these partially discovered devices are never exposed, but algorithm that filters-off devices, shadowed by static configuration, requires names of all discovered devices, and if device doesn't have DNS-SD "buddy", its name is taken from model name (because in the WSD world devices doesn't have network names).

tangyanli commented 4 years ago

Hi, Alexander

I have tested the new code, the sane_close() issue is fixed too. Thanks for your explanation. I will read it carefully later. :-) All the problem are fixed, so I close this issue.

tangyanli commented 4 years ago

Hi, Alexander

Can I ask you a question... What does the HTTP endpoints mean?

Get/GetResponse brings device metadata: it's name, model, and HTTP endpoints for particular functions (printing/scanning etc).

And why does the device metadata contain HTTP endpoints too?

alexpevzner commented 4 years ago

All the problem are fixed, so I close this issue.

Thank you, Tess! Let it be 0.99.18 now!

What does the HTTP endpoints mean?

Some base URL to send requests to. It either can be uses "as is", as WSD does, or URLs, relative to this base URL, can be used, as eSCL does, but in any case, you need to know only a single base URL to communicate with some service.

However, real devices may offer multiple endpoints for the same protocol. For example, IP4/IP6, or Ethernet/WiFi (if device uses different addresses for its Ethernet and WiFi interfaces, as they usually do), or HTTP/HTTPS