vnsprintf returned -1 in log_vwrite -- bizarre.

[Axel Pettinger <api () worldonline de>]

Hi,

I used Nmap 4.20ALPHA8 to scan a few computers and noticed that Nmap
had problems with three of these computers when writing the log file 
- examples see below. The error line was:

vnsprintf returned -1 in log_vwrite -- bizarre. Quitting.

What was wrong here?

Regards,
Axel Pettinger


---
Example 1
---------
Logfile contains:

# Nmap 4.20ALPHA8 scan initiated Thu Oct 05 16:59:29 2006 as: <nmap-path>\nmap.exe -O2 -sSU -F -T4 -d -v -v -oN 
<log-name> <target1> 
Interesting ports on <target1>:
Not shown: 1648 closed ports


Command Line Output:

<nmap-path>\nmap.exe -O2 -sSU -F -T4 -d -v -v -o
N <log-name> <target1>
Winpcap present, dynamic linked to: WinPcap version 3.1 (packet.dll version 3, 1
, 0, 27), based on libpcap version 0.9[.x]

Starting Nmap 4.20ALPHA8 ( http://insecure.org/nmap ) at 2006-10-05 16:59 W. Eur
ope Daylight Time
--------------- Timing report ---------------
  hostgroups: min 1, max 100000
  rtt-timeouts: init 500, min 100, max 1250
  msx-scan-delay: TCP 10, UDP 1000
  parallelism: min 0, max 0
  max-retries: 6, host-timeout: 0
---------------------------------------------
Initiating ARP Ping Scan at 16:59
Scanning <target1> [1 port]
Packet capture filter (device eth0): arp and ether dst host 00:0E:7F:69:78:F9
Completed ARP Ping Scan at 16:59, 0.34s elapsed (1 total hosts)
mass_rdns: Using DNS server <DNS1>
mass_rdns: Using DNS server <DNS2>
Initiating Parallel DNS resolution of 1 host. at 16:59
mass_rdns: 0.02s 0/1 [#: 2, OK: 0, NX: 0, DR: 0, SF: 0, TR: 1]
Completed Parallel DNS resolution of 1 host. at 16:59, 0.00s elapsed
DNS resolution of 1 IPs took 0.02s. Mode: Async [#: 2, OK: 0, NX: 1, DR: 0, SF:
0, TR: 1, CN: 0]
Initiating SYN Stealth Scan at 16:59
Scanning <target1> [1249 ports]
Packet capture filter (device eth0): dst host <host> and (icmp or (tcp and
(src host <target1>)))
Discovered open port 80/tcp on <target1>
Discovered open port 23/tcp on <target1>
Discovered open port 1008/tcp on <target1>
Discovered open port 513/tcp on <target1>
Increased max_successful_tryno for <target1> to 1 (packet drop)
Discovered open port 111/tcp on <target1>
Completed SYN Stealth Scan at 16:59, 3.31s elapsed (1249 total ports)
Initiating UDP Scan at 16:59
Scanning <target1> [1017 ports]
Packet capture filter (device eth0): dst host <host> and (icmp or (udp and
(src host <target1>)))
Increased max_successful_tryno for <target1> to 1 (packet drop)
Increased max_successful_tryno for <target1> to 2 (packet drop)
Increased max_successful_tryno for <target1> to 3 (packet drop)
UDP Scan Timing: About 46.84% done; ETC: 17:00 (0:00:34 remaining)
UDP Scan Timing: About 50.93% done; ETC: 17:01 (0:00:57 remaining)
UDP Scan Timing: About 55.10% done; ETC: 17:02 (0:01:13 remaining)
Increased max_successful_tryno for <target1> to 4 (packet drop)
UDP Scan Timing: About 55.28% done; ETC: 17:03 (0:01:37 remaining)
UDP Scan Timing: About 58.05% done; ETC: 17:03 (0:01:48 remaining)
UDP Scan Timing: About 60.82% done; ETC: 17:04 (0:01:56 remaining)
Increased max_successful_tryno for <target1> to 5 (packet drop)
Increasing send delay for <target1> from 0 to 50 due to max_successful_tryno in
crease to 5
UDP Scan Timing: About 60.23% done; ETC: 17:05 (0:02:19 remaining)
UDP Scan Timing: About 62.75% done; ETC: 17:05 (0:02:22 remaining)
Increasing send delay for <target1> from 50 to 100 due to 11 out of 11 dropped
probes since last increase.
UDP Scan Timing: About 65.36% done; ETC: 17:06 (0:02:23 remaining)
UDP Scan Timing: About 67.99% done; ETC: 17:06 (0:02:21 remaining)
Increasing send delay for <target1> from 100 to 200 due to 11 out of 11 dropped
 probes since last increase.
Increased max_successful_tryno for <target1> to 6 (packet drop)
Increasing send delay for <target1> from 200 to 400 due to max_successful_tryno
 increase to 6
Warning: Giving up on port early because retransmission cap hit.
Increasing send delay for <target1> from 400 to 800 due to 11 out of 11 dropped
 probes since last increase.
Increasing send delay for <target1> from 800 to 1000 due to 11 out of 11 droppe
d probes since last increase.
Completed UDP Scan at 17:44, 2702.37s elapsed (1017 total ports)
Packet capture filter (device eth0): dst host <host> and (icmp or (tcp and
(src host <target1>)))
Initiating OS detection against <target1>
OS detection timingRatio() == (1160063076.230 - 1160063075.683) * 1000 / 500 ==
1.094
Retrying OS detection against <target1>
OS detection timingRatio() == (1160063078.449 - 1160063077.902) * 1000 / 500 ==
1.094
Retrying OS detection against <target1>
OS detection timingRatio() == (1160063080.668 - 1160063080.121) * 1000 / 500 ==
1.094
Host <target1> appears to be up ... good.
Interesting ports on <target1>:
Not shown: 1648 closed ports
vnsprintf returned -1 in log_vwrite -- bizarre. Quitting.
###############################################################################

---
Example 2
---------
Logfile contains:

# Nmap 4.20ALPHA8 scan initiated Thu Oct 05 20:11:49 2006 as: <nmap-path>\nmap.exe -O2 -sSU -p1-65535 -T4 -d -v -v -oN 
<log-name> <target2> 
Interesting ports on <target2>:
Not shown: 130458 closed ports

Command Line Output:

(...)
UDP Scan Timing: About 99.93% done; ETC: 13:41 (0:00:46 remaining)
Completed UDP Scan at 14:14, 64940.83s elapsed (65535 total ports)
Packet capture filter (device eth0): dst host <host> and (icmp or (tcp and
(src host <target2>)))
Initiating OS detection against <target2>
OS detection timingRatio() == (1160136877.205 - 1160136876.657) * 1000 / 500 ==
1.096
Retrying OS detection against <target2>
OS detection timingRatio() == (1160136879.711 - 1160136879.163) * 1000 / 500 ==
1.096
Retrying OS detection against <target2>
Unable to associate os scan response with sent packet for <target2>.
Received ack: 6FD96365; sequence sent: 3F41121A. Packet:
TCP packet: <target2>:22 -> <host>:55886 (total: 60 bytes)
Flags: SYN ACK
ipid: 0 ttl: 64 Seq: 156279841  Ack: 1876517733
Unable to associate os scan response with sent packet for <target2>.
Received ack: 6FD96366; sequence sent: 3F41121A. Packet:
TCP packet: <target2>:22 -> <host>:55887 (total: 60 bytes)
Flags: SYN ACK
ipid: 0 ttl: 64 Seq: 162107402  Ack: 1876517734
Unable to associate os scan response with sent packet for <target2>.
Received ack: 6FD96364; sequence sent: 3F41121A. Packet:
TCP packet: <target2>:22 -> <host>:55885 (total: 60 bytes)
Flags: SYN ACK
ipid: 0 ttl: 64 Seq: 156099826  Ack: 1876517732
Unable to associate os scan response with sent packet for <target2>.
Received ack: 6FD96369; sequence sent: 3F41121A. Packet:
TCP packet: <target2>:22 -> <host>:55890 (total: 56 bytes)
Flags: SYN ACK
ipid: 0 ttl: 64 Seq: 164169254  Ack: 1876517737
Unable to associate os scan response with sent packet for <target2>.
Received ack: 6FD96367; sequence sent: 3F41121A. Packet:
TCP packet: <target2>:22 -> <host>:55888 (total: 60 bytes)
Flags: SYN ACK
ipid: 0 ttl: 64 Seq: 164844687  Ack: 1876517735
Unable to associate os scan response with sent packet for <target2>.
Received ack: 6FD96368; sequence sent: 3F41121A. Packet:
TCP packet: <target2>:22 -> <host>:55889 (total: 60 bytes)
Flags: SYN ACK
ipid: 0 ttl: 64 Seq: 162881015  Ack: 1876517736
OS detection timingRatio() == (1160136882.327 - 1160136881.779) * 1000 / 500 ==
1.096
Host <target2> appears to be up ... good.
Interesting ports on <target2>:
Not shown: 130458 closed ports
vnsprintf returned -1 in log_vwrite -- bizarre. Quitting.
###############################################################################

---
Example 3
---------
Logfile contains:

# Nmap 4.20ALPHA8 scan initiated Thu Oct 05 20:12:39 2006 as: <nmap-path>\nmap.exe -O2 -sSU -p1-65535 -T4 -d -v -v -oN 
<log-name> <target3> 
Insufficient responses for TCP sequencing (3), OS detection may be less accurate
Interesting ports on <target-hostname3> (<target3>):
Not shown: 130779 closed ports

Command Line Output:

(...)
UDP Scan Timing: About 99.96% done; ETC: 17:24 (0:00:30 remaining)
Discovered open port 69/udp on <target3>
Completed UDP Scan at 17:54, 78045.13s elapsed (65535 total ports)
Packet capture filter (device eth0): dst host <host> and (icmp or (tcp and
(src host <target3>)))
Initiating OS detection against <target-hostname> (<target3>)
OS detection timingRatio() == (1160150088.349 - 1160150087.802) * 1000 / 500 ==
1.094
Retrying OS detection against <target-hostname> (<target3>)
Unable to associate os scan response with sent packet for <target3>.
Received ack: 11901D1B; sequence sent: 297E6575. Packet:
TCP packet: <target3>:23 -> <host>:63326 (total: 60 bytes)
Flags: SYN ACK
ipid: 0 ttl: 64 Seq: 3187377482 Ack: 294657307
Unable to associate os scan response with sent packet for <target3>.
Received ack: 11901D19; sequence sent: 297E6575. Packet:
TCP packet: <target3>:23 -> <host>:63324 (total: 60 bytes)
Flags: SYN ACK
ipid: 0 ttl: 64 Seq: 3177798742 Ack: 294657305
Unable to associate os scan response with sent packet for <target3>.
Received ack: 11901D17; sequence sent: 297E6575. Packet:
TCP packet: <target3>:23 -> <host>:63322 (total: 60 bytes)
Flags: SYN ACK
ipid: 0 ttl: 64 Seq: 3184698054 Ack: 294657303
Insufficient responses for TCP sequencing (3), OS detection may be less accurate

OS detection timingRatio() == (1160150091.615 - 1160150091.068) * 1000 / 500 ==
1.094
WARNING:  OS didn't match until the try #2
Host <target-hostname> (<target3>) appears to be up ... good.
Interesting ports on <target-hostname> (<target3>):
Not shown: 130779 closed ports
vnsprintf returned -1 in log_vwrite -- bizarre. Quitting.
###############################################################################

_______________________________________________
Sent through the nmap-dev mailing list
http://cgi.insecure.org/mailman/listinfo/nmap-dev
Archived at http://SecLists.Org