Weirdness with Mac stdout

[l3nz]

I have a small thing that decodes ip addresses using an online service, and then prints them out.

I create a big string, and then print it out. Sometimes when I println it out, it’s all garbled… but only if I print it out on stdout. If I redirect it, to a file, it works. If I use prn, as in the example below, it works.

"\n\n1.4.174.X AS23969 TOT Public Company Lim, Bangkok, TH\n13.68.212.X AS8075 Microsoft Corporation, Hampden Sydney, Virginia, US\n13.82.19.Y AS8075 Microsoft Corporation, Hampden Sydney, Virginia, US\n15.228.3.X AS16509 Amazon.com, Sao Paulo, BR....""


1.4.174.X AS23969 TOT Public Company Lim, Bangkok, TH
13.68.212.X AS8075 Microsoft Corporation, Hampden Sydney, Virginia, US
tion, Hampden Sydney, Virginia, USra
15.228.3.X AS16509 Amazon.com, Sao Paulo, BR

Any ideas? I feel a bit lost.

[thheller]

This looks like you are using multiple threads that try to print in parallel. Since by default there is no locking they’ll just race each other and get a print a few bytes interleaved leading the the garbled output.

The best path forward would be using one of the common logging libraries since they handle this for you. Another ad-hoc option would be to do the locking yourself but unless everything is printed using that lock you might still end up with the garbled output at some point.

;; declare this where all threads can easily access it
;; typically a global def is fine
(defonce print-lock (Object.))

;; and then whenever you print you wrap it with the locking macro
(locking print-lock
   (println the-string))

You must take absolute care holding the lock only very short periods. You will be granting exclusive access to one thread only so holding the lock for too long might block other threads too long or even deadlock yourself if you are not careful.

[l3nz]

That’s what I thought initially - it would make a lot of sense. But the actual code is like:

(defn spy [v]
  (prn v)
  v)

;
;
  (-> file
      slurp
      stringToIpList
      processIps  ;; returns a formatted string
      spy
      println))

and I added the spy to understand what was happening. And in fact it is one single string… as printed above.

The only weirdness - but I don’t see how it might affect stdout - is that the actual results are computed asynchronously

(defn processIps [ips]
  (let [futures (doall (map #(future (beautifulName (getIp %))) ips))
        solved (mapv deref futures)]

    (apply str
           "\n\n"
           (mapv #(str %1 " " %2 "\n")
                ips
                solved))))

But who cares? once you return the string, all those futures are dereferenced, so nothing bad.

[l3nz]

Also, if I run:

myscript | less

output is printed correcty.

[seancorfield]

Are you sure you only have that one println in the program? If you have some leftover debugging that is printing things, you would likely see some interleaving of output.

[mars0i]

I have no idea, and people who’ve responded know more than I do, but here are some thoughts:

Why are there two quotation marks at the end of the constructed string in your first post? Is this just a typo in the post? I think so, because I don’t see how the code you listed will generate that. But if there really is an extra quotation mark in what’s passed to println, if that is what println is processing, then it might think it’s receiving two strings. Maybe by passing the string through a pipe (to less) or redirecting to a file, you are getting help from the shell or less which is cleaning up the extra quotation mark or ignoring it. (Is the extra quotation mark in the file?)

Does it make a difference if you add (flush) to flush buffered output? (I don’t think it should help, but sometimes that’s helped me when when I have problems with garbled printing to stdout.)